DEV 1666: Fix /end requests and clean up logging (#109)

* ensure /end request is always called, and refactor win/draw logic

* clean up logging and error handling during initialization

* automatically generate friendly snake names

* title-case snake names

* print out list of alive snake names instead of count

* log snake names, IDs, and URLs at startup

* print out state for turn zero

board/server.go

@@ -3,12 +3,12 @@ package board
 import (
 	"context"
 	"encoding/json"
-	"log"
 	"net"
 	"net/http"
 
 	"github.com/gorilla/websocket"
 	"github.com/rs/cors"
+	log "github.com/spf13/jwalterweatherman"
 )
 
 // A minimal server capable of handling the requests from a single browser client running the board viewer.
@@ -51,7 +51,7 @@ func (server *BoardServer) handleGame(w http.ResponseWriter, r *http.Request) {
 		Game Game
 	}{server.game})
 	if err != nil {
-		log.Printf("Unable to serialize game: %v", err)
+		log.ERROR.Printf("Unable to serialize game: %v", err)
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
@@ -61,37 +61,37 @@ func (server *BoardServer) handleGame(w http.ResponseWriter, r *http.Request) {
 func (server *BoardServer) handleWebsocket(w http.ResponseWriter, r *http.Request) {
 	ws, err := upgrader.Upgrade(w, r, nil)
 	if err != nil {
-		log.Printf("Unable to upgrade connection: %v", err)
+		log.ERROR.Printf("Unable to upgrade connection: %v", err)
 		return
 	}
 
 	defer func() {
 		err = ws.Close()
 		if err != nil {
-			log.Printf("Unable to close websocket stream")
+			log.ERROR.Printf("Unable to close websocket stream")
 		}
 	}()
 
 	for event := range server.events {
 		jsonStr, err := json.Marshal(event)
 		if err != nil {
-			log.Printf("Unable to serialize event for websocket: %v", err)
+			log.ERROR.Printf("Unable to serialize event for websocket: %v", err)
 		}
 
 		err = ws.WriteMessage(websocket.TextMessage, jsonStr)
 		if err != nil {
-			log.Printf("Unable to write to websocket: %v", err)
+			log.ERROR.Printf("Unable to write to websocket: %v", err)
 			break
 		}
 	}
 
-	log.Printf("Finished writing all game events, signalling game server to stop")
+	log.DEBUG.Printf("Finished writing all game events, signalling game server to stop")
 	close(server.done)
 
-	log.Printf("Sending websocket close message")
+	log.DEBUG.Printf("Sending websocket close message")
 	err = ws.WriteMessage(websocket.CloseMessage, websocket.FormatCloseMessage(websocket.CloseNormalClosure, ""))
 	if err != nil {
-		log.Printf("Problem closing websocket: %v", err)
+		log.ERROR.Printf("Problem closing websocket: %v", err)
 	}
 }
 
@@ -103,7 +103,7 @@ func (server *BoardServer) Listen() (string, error) {
 	go func() {
 		err = server.httpServer.Serve(listener)
 		if err != http.ErrServerClosed {
-			log.Printf("Error in board HTTP server: %v", err)
+			log.ERROR.Printf("Error in board HTTP server: %v", err)
 		}
 	}()
 
@@ -115,13 +115,13 @@ func (server *BoardServer) Listen() (string, error) {
 func (server *BoardServer) Shutdown() {
 	close(server.events)
 
-	log.Printf("Waiting for websocket clients to finish")
+	log.DEBUG.Printf("Waiting for websocket clients to finish")
 	<-server.done
-	log.Printf("Server is done, exiting")
+	log.DEBUG.Printf("Server is done, exiting")
 
 	err := server.httpServer.Shutdown(context.Background())
 	if err != nil {
-		log.Printf("Error shutting down HTTP server: %v", err)
+		log.ERROR.Printf("Error shutting down HTTP server: %v", err)
 	}
 }
 

cli/commands/info.go

@@ -2,10 +2,11 @@ package commands
 
 import (
 	"fmt"
-	"log"
+
+	"github.com/spf13/cobra"
+	log "github.com/spf13/jwalterweatherman"
 
 	"github.com/BattlesnakeOfficial/rules/maps"
-	"github.com/spf13/cobra"
 )
 
 type mapInfo struct {
@@ -35,7 +36,7 @@ func NewMapInfoCommand() *cobra.Command {
 			if len(args) < 1 {
 				err := cmd.Help()
 				if err != nil {
-					log.Fatal(err)
+					log.ERROR.Fatal(err)
 				}
 				return
 			}
@@ -59,7 +60,7 @@ func NewMapInfoCommand() *cobra.Command {
 func (m *mapInfo) display(id string) {
 	gameMap, err := maps.GetMap(id)
 	if err != nil {
-		log.Fatalf("Failed to load game map %#v: %v", id, err)
+		log.ERROR.Fatalf("Failed to load game map %v: %v", id, err)
 	}
 	meta := gameMap.Meta()
 	fmt.Println("Name:", meta.Name)

cli/commands/map.go

@@ -1,9 +1,8 @@
 package commands
 
 import (
-	"log"
-
 	"github.com/spf13/cobra"
+	log "github.com/spf13/jwalterweatherman"
 )
 
 func NewMapCommand() *cobra.Command {
@@ -15,7 +14,7 @@ func NewMapCommand() *cobra.Command {
 		Run: func(cmd *cobra.Command, args []string) {
 			err := cmd.Help()
 			if err != nil {
-				log.Fatal(err)
+				log.ERROR.Fatal(err)
 			}
 		},
 	}

cli/commands/names.go

@@ -0,0 +1,153 @@
+// This file uses material from the Wikipedia article <a href="https://en.wikipedia.org/wiki/List_of_snakes_by_common_name">"List of snakes by common name"</a>, which is released under the <a href="https://creativecommons.org/licenses/by-sa/3.0/">Creative Commons Attribution-Share-Alike License 3.0</a>.
+package commands
+
+import (
+	"math/rand"
+	"time"
+
+	"github.com/google/uuid"
+)
+
+var snakeNames = []string{
+	"Adder",
+	"Aesculapian Snake",
+	"Anaconda",
+	"Arafura File Snake",
+	"Asp",
+	"African Beaked Snake",
+	"Ball Python",
+	"Bird Snake",
+	"Black-headed Snake",
+	"Mexican Black Kingsnake",
+	"Black Rat Snake",
+	"Black Snake",
+	"Blind Snake",
+	"Boa",
+	"Boiga",
+	"Boomslang",
+	"Brown Snake",
+	"Bull Snake",
+	"Bushmaster",
+	"Dwarf Beaked Snake",
+	"Rufous Beaked Snake",
+	"Canebrake",
+	"Cantil",
+	"Cascabel",
+	"Cat-eyed Snake",
+	"Cat Snake",
+	"Chicken Snake",
+	"Coachwhip Snake",
+	"Cobra",
+	"Collett's Snake",
+	"Congo Snake",
+	"Copperhead",
+	"Coral Snake",
+	"Corn Snake",
+	"Cottonmouth",
+	"Crowned Snake",
+	"Cuban Wood Snake",
+	"Egg-eater",
+	"Eyelash Viper",
+	"Fer-de-lance",
+	"Fierce Snake",
+	"Fishing Snake",
+	"Flying Snake",
+	"Fox Snake",
+	"Forest Flame Snake",
+	"Garter Snake",
+	"Glossy Snake",
+	"Gopher Snake",
+	"Grass Snake",
+	"Green Snake",
+	"Ground Snake",
+	"Habu",
+	"Harlequin Snake",
+	"Herald Snake",
+	"Hognose Snake",
+	"Hoop Snake",
+	"Hundred Pacer",
+	"Ikaheka Snake",
+	"Indigo Snake",
+	"Jamaican Tree Snake",
+	"Jararacussu",
+	"Keelback",
+	"King Brown",
+	"King Cobra",
+	"King Snake",
+	"Krait",
+	"Lancehead",
+	"Lora",
+	"Lyre Snake",
+	"Machete Savane",
+	"Mamba",
+	"Mamushi",
+	"Mangrove Snake",
+	"Milk Snake",
+	"Moccasin Snake",
+	"Montpellier Snake",
+	"Mud Snake",
+	"Mussurana",
+	"Night Snake",
+	"Nose-horned Viper",
+	"Parrot Snake",
+	"Patchnose Snake",
+	"Pine Snake",
+	"Pipe Snake",
+	"Python",
+	"Queen Snake",
+	"Racer",
+	"Raddysnake",
+	"Rat Snake",
+	"Rattlesnake",
+	"Ribbon Snake",
+	"Rinkhals",
+	"River Jack",
+	"Sea Snake",
+	"Shield-tailed Snake",
+	"Sidewinder",
+	"Small-eyed Snake",
+	"Stiletto Snake",
+	"Striped Snake",
+	"Sunbeam Snake",
+	"Taipan",
+	"Tentacled Snake",
+	"Tic Polonga",
+	"Tiger Snake",
+	"Tigre Snake",
+	"Tree Snake",
+	"Trinket Snake",
+	"Twig Snake",
+	"Twin Headed King Snake",
+	"Titanoboa",
+	"Urutu",
+	"Vine Snake",
+	"Viper",
+	"Wart Snake",
+	"Water Moccasin",
+	"Water Snake",
+	"Whip Snake",
+	"Wolf Snake",
+	"Worm Snake",
+	"Wutu",
+	"Yarara",
+	"Zebra Snake",
+}
+
+func init() {
+	randGen := rand.New(rand.NewSource(time.Now().UnixNano()))
+	randGen.Shuffle(len(snakeNames), func(i, j int) {
+		snakeNames[i], snakeNames[j] = snakeNames[j], snakeNames[i]
+	})
+}
+
+// Generate a random unique snake name, or return a UUID if there are no more names available.
+func GenerateSnakeName() string {
+	if len(snakeNames) == 0 {
+		return uuid.New().String()
+	}
+
+	name := snakeNames[0]
+	snakeNames = snakeNames[1:]
+
+	return name
+}

cli/commands/output.go

@@ -3,9 +3,10 @@ package commands
 import (
 	"encoding/json"
 	"fmt"
-	"log"
 	"os"
 
+	log "github.com/spf13/jwalterweatherman"
+
 	"github.com/BattlesnakeOfficial/rules/client"
 )
 
@@ -30,7 +31,7 @@ func (ge *GameExporter) FlushToFile(filepath string, format string) error {
 	if format == "JSONL" {
 		formattedOutput, formattingErr = ge.ConvertToJSON()
 	} else {
-		log.Fatalf("Invalid output format passed: %s", format)
+		log.ERROR.Fatalf("Invalid output format passed: %s", format)
 	}
 
 	if formattingErr != nil {
@@ -50,7 +51,7 @@ func (ge *GameExporter) FlushToFile(filepath string, format string) error {
 		}
 	}
 
-	log.Printf("Written %d lines of output to file: %s\n", len(formattedOutput), filepath)
+	log.DEBUG.Printf("Written %d lines of output to file: %s\n", len(formattedOutput), filepath)
 
 	return nil
 }

cli/commands/play.go

@@ -5,13 +5,12 @@ import (
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"math/rand"
 	"net/http"
 	"net/url"
-	"os"
 	"path"
 	"strconv"
+	"strings"
 	"sync"
 	"time"
 
@@ -22,6 +21,7 @@ import (
 	"github.com/google/uuid"
 	"github.com/pkg/browser"
 	"github.com/spf13/cobra"
+	log "github.com/spf13/jwalterweatherman"
 )
 
 // Used to store state for each SnakeState while running a local game
@@ -55,7 +55,6 @@ type GameState struct {
 	UseColor            bool
 	Seed                int64
 	TurnDelay           int
-	DebugRequests       bool
 	Output              string
 	ViewInBrowser       bool
 	BoardURL            string
@@ -98,7 +97,6 @@ func NewPlayCommand() *cobra.Command {
 	playCmd.Flags().Int64VarP(&gameState.Seed, "seed", "r", time.Now().UTC().UnixNano(), "Random Seed")
 	playCmd.Flags().IntVarP(&gameState.TurnDelay, "delay", "d", 0, "Turn Delay in Milliseconds")
 	playCmd.Flags().IntVarP(&gameState.TurnDuration, "duration", "D", 0, "Minimum Turn Duration in Milliseconds")
-	playCmd.Flags().BoolVar(&gameState.DebugRequests, "debug-requests", false, "Log body of all requests sent")
 	playCmd.Flags().StringVarP(&gameState.Output, "output", "o", "", "File path to output game state to. Existing files will be overwritten")
 	playCmd.Flags().BoolVar(&gameState.ViewInBrowser, "browser", false, "View the game in the browser using the Battlesnake game board")
 	playCmd.Flags().StringVar(&gameState.BoardURL, "board-url", "https://board.battlesnake.com", "Base URL for the game board when using --browser")
@@ -129,7 +127,7 @@ func (gameState *GameState) initialize() {
 	// Load game map
 	gameMap, err := maps.GetMap(gameState.MapName)
 	if err != nil {
-		log.Fatalf("Failed to load game map %#v: %v", gameState.MapName, err)
+		log.ERROR.Fatalf("Failed to load game map %#v: %v", gameState.MapName, err)
 	}
 	gameState.gameMap = gameMap
 
@@ -173,10 +171,6 @@ func (gameState *GameState) Run() {
 		isDraw:        false,
 	}
 
-	if gameState.ViewMap {
-		gameState.printMap(boardState)
-	}
-
 	boardGame := board.Game{
 		ID:     gameState.gameID,
 		Status: "running",
@@ -194,23 +188,30 @@ func (gameState *GameState) Run() {
 	if gameState.ViewInBrowser {
 		serverURL, err := boardServer.Listen()
 		if err != nil {
-			log.Fatalf("Error starting HTTP server: %v", err)
+			log.ERROR.Fatalf("Error starting HTTP server: %v", err)
 		}
-		log.Printf("Board server listening on %s", serverURL)
+		defer boardServer.Shutdown()
+		log.INFO.Printf("Board server listening on %s", serverURL)
 
 		boardURL := fmt.Sprintf(gameState.BoardURL+"?engine=%s&game=%s&autoplay=true", serverURL, gameState.gameID)
 
-		log.Printf("Opening board URL: %s", boardURL)
+		log.INFO.Printf("Opening board URL: %s", boardURL)
 		if err := browser.OpenURL(boardURL); err != nil {
-			log.Printf("Failed to open browser: %v", err)
+			log.ERROR.Printf("Failed to open browser: %v", err)
-		}
 		}
 
-	if gameState.ViewInBrowser {
 		// send turn zero to websocket server
 		boardServer.SendEvent(gameState.buildFrameEvent(boardState))
 	}
 
+	log.INFO.Printf("Ruleset: %v, Seed: %v", gameState.GameType, gameState.Seed)
+
+	if gameState.ViewMap {
+		gameState.printMap(boardState)
+	} else {
+		gameState.printState(boardState)
+	}
+
 	var endTime time.Time
 	for v := false; !v; v, _ = gameState.ruleset.IsGameOver(boardState) {
 		if gameState.TurnDuration > 0 {
@@ -238,7 +239,7 @@ func (gameState *GameState) Run() {
 		if gameState.ViewMap {
 			gameState.printMap(boardState)
 		} else {
-			log.Printf("[%v]: State: %v\n", boardState.Turn, boardState)
+			gameState.printState(boardState)
 		}
 
 		if gameState.TurnDelay > 0 {
@@ -254,36 +255,29 @@ func (gameState *GameState) Run() {
 		}
 	}
 
-	isDraw := true
+	gameExporter.isDraw = false
-	if gameState.GameType == "solo" {
+
-		log.Printf("[DONE]: Game completed after %v turns.", boardState.Turn)
+	if len(gameState.snakeStates) > 1 {
-		if exportGame {
+		// A draw is possible if there is more than one snake in the game.
-			// These checks for exportGame are present to avoid vacuuming up RAM when an export is not requred.
+		gameExporter.isDraw = true
-			for _, snakeState := range gameState.snakeStates {
-				gameExporter.winner = snakeState
-				break
 	}
-		}
+
-	} else {
-		var winner SnakeState
 	for _, snake := range boardState.Snakes {
 		snakeState := gameState.snakeStates[snake.ID]
 		if snake.EliminatedCause == rules.NotEliminated {
-				isDraw = false
+			gameExporter.isDraw = false
-				winner = snakeState
+			gameExporter.winner = snakeState
 		}
+
 		gameState.sendEndRequest(boardState, snakeState)
 	}
 
-		if isDraw {
+	if gameExporter.isDraw {
-			log.Printf("[DONE]: Game completed after %v turns. It was a draw.", boardState.Turn)
+		log.INFO.Printf("Game completed after %v turns. It was a draw.", boardState.Turn)
+	} else if gameExporter.winner.Name != "" {
+		log.INFO.Printf("Game completed after %v turns. %v was the winner.", boardState.Turn, gameExporter.winner.Name)
 	} else {
-			log.Printf("[DONE]: Game completed after %v turns. %v is the winner.", boardState.Turn, winner.Name)
+		log.INFO.Printf("Game completed after %v turns.", boardState.Turn)
-		}
-		if exportGame {
-			gameExporter.winner = winner
-			gameExporter.isDraw = isDraw
-		}
 	}
 
 	if gameState.ViewInBrowser {
@@ -296,14 +290,9 @@ func (gameState *GameState) Run() {
 	if exportGame {
 		err := gameExporter.FlushToFile(gameState.Output, "JSONL")
 		if err != nil {
-			log.Printf("[WARN]: Unable to export game. Reason: %v\n", err.Error())
+			log.ERROR.Fatalf("Unable to export game. Reason: %v", err)
-			os.Exit(1)
 		}
 	}
-
-	if gameState.ViewInBrowser {
-		boardServer.Shutdown()
-	}
 }
 
 func (gameState *GameState) initializeBoardFromArgs() *rules.BoardState {
@@ -313,11 +302,11 @@ func (gameState *GameState) initializeBoardFromArgs() *rules.BoardState {
 	}
 	boardState, err := maps.SetupBoard(gameState.gameMap.ID(), gameState.ruleset.Settings(), gameState.Width, gameState.Height, snakeIds)
 	if err != nil {
-		log.Fatalf("Error Initializing Board State: %v", err)
+		log.ERROR.Fatalf("Error Initializing Board State: %v", err)
 	}
 	boardState, err = gameState.ruleset.ModifyInitialBoardState(boardState)
 	if err != nil {
-		log.Fatalf("Error Initializing Board State: %v", err)
+		log.ERROR.Fatalf("Error Initializing Board State: %v", err)
 	}
 
 	for _, snakeState := range gameState.snakeStates {
@@ -325,12 +314,10 @@ func (gameState *GameState) initializeBoardFromArgs() *rules.BoardState {
 		requestBody := serialiseSnakeRequest(snakeRequest)
 		u, _ := url.ParseRequestURI(snakeState.URL)
 		u.Path = path.Join(u.Path, "start")
-		if gameState.DebugRequests {
+		log.DEBUG.Printf("POST %s: %v", u, string(requestBody))
-			log.Printf("POST %s: %v", u, string(requestBody))
-		}
 		_, err = gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
 		if err != nil {
-			log.Printf("[WARN]: Request to %v failed", u.String())
+			log.WARN.Printf("Request to %v failed", u.String())
 		}
 	}
 	return boardState
@@ -376,12 +363,12 @@ func (gameState *GameState) createNextBoardState(boardState *rules.BoardState) *
 	}
 	boardState, err := gameState.ruleset.CreateNextBoardState(boardState, moves)
 	if err != nil {
-		log.Fatalf("Error producing next board state: %v", err)
+		log.ERROR.Fatalf("Error producing next board state: %v", err)
 	}
 
 	boardState, err = maps.UpdateBoard(gameState.gameMap.ID(), boardState, gameState.ruleset.Settings())
 	if err != nil {
-		log.Fatalf("Error updating board with game map: %v", err)
+		log.ERROR.Fatalf("Error updating board with game map: %v", err)
 	}
 
 	boardState.Turn += 1
@@ -394,54 +381,52 @@ func (gameState *GameState) getMoveForSnake(boardState *rules.BoardState, snakeS
 	requestBody := serialiseSnakeRequest(snakeRequest)
 	u, _ := url.ParseRequestURI(snakeState.URL)
 	u.Path = path.Join(u.Path, "move")
-	if gameState.DebugRequests {
+	log.DEBUG.Printf("POST %s: %v", u, string(requestBody))
-		log.Printf("POST %s: %v", u, string(requestBody))
-	}
 	res, err := gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
 
 	// Use snake's last move as the default in case of an error
 	snakeMove := rules.SnakeMove{ID: snakeState.ID, Move: snakeState.LastMove}
 
 	if err != nil {
-		log.Printf(
+		log.WARN.Printf(
-			"[WARN]: Request to %v failed\n"+
+			"Request to %v failed\n"+
-				"\tError: %s\n", u.String(), err)
+				"\tError: %s", u.String(), err)
 		return snakeMove
 	}
 	if res.Body == nil {
-		log.Printf(
+		log.WARN.Printf(
-			"[WARN]: Failed to parse response from %v\n"+
+			"Failed to parse response from %v\n"+
-				"\tError: body is empty\n", u.String())
+				"\tError: body is empty", u.String())
 		return snakeMove
 	}
 	defer res.Body.Close()
 	body, readErr := ioutil.ReadAll(res.Body)
 	if readErr != nil {
-		log.Printf(
+		log.WARN.Printf(
-			"[WARN]: Failed to read response body from %v\n"+
+			"Failed to read response body from %v\n"+
-				"\tError: %v\n", u.String(), readErr)
+				"\tError: %v", u.String(), readErr)
 		return snakeMove
 	}
 	if res.StatusCode != http.StatusOK {
-		log.Printf(
+		log.WARN.Printf(
-			"[WARN]: Got non-ok status code from %v\n"+
+			"Got non-ok status code from %v\n"+
 				"\tStatusCode: %d (expected %d)\n"+
-				"\tBody: %q\n", u.String(), res.StatusCode, http.StatusOK, body)
+				"\tBody: %q", u.String(), res.StatusCode, http.StatusOK, body)
 		return snakeMove
 	}
 	playerResponse := client.MoveResponse{}
 	jsonErr := json.Unmarshal(body, &playerResponse)
 	if jsonErr != nil {
-		log.Printf(
+		log.WARN.Printf(
-			"[WARN]: Failed to decode JSON from %v\n"+
+			"Failed to decode JSON from %v\n"+
 				"\tError: %v\n"+
 				"\tBody: %q\n"+
 				"\tSee https://docs.battlesnake.com/references/api#post-move", u.String(), jsonErr, body)
 		return snakeMove
 	}
 	if playerResponse.Move != "up" && playerResponse.Move != "down" && playerResponse.Move != "left" && playerResponse.Move != "right" {
-		log.Printf(
+		log.WARN.Printf(
-			"[WARN]: Failed to parse JSON data from %v\n"+
+			"Failed to parse JSON data from %v\n"+
 				"\tError: invalid move %q, valid moves are \"up\", \"down\", \"left\" or \"right\"\n"+
 				"\tBody: %q\n"+
 				"\tSee https://docs.battlesnake.com/references/api#post-move", u.String(), playerResponse.Move, body)
@@ -457,12 +442,10 @@ func (gameState *GameState) sendEndRequest(boardState *rules.BoardState, snakeSt
 	requestBody := serialiseSnakeRequest(snakeRequest)
 	u, _ := url.ParseRequestURI(snakeState.URL)
 	u.Path = path.Join(u.Path, "end")
-	if gameState.DebugRequests {
+	log.DEBUG.Printf("POST %s: %v", u, string(requestBody))
-		log.Printf("POST %s: %v", u, string(requestBody))
-	}
 	_, err := gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
 	if err != nil {
-		log.Printf("[WARN]: Request to %v failed", u.String())
+		log.WARN.Printf("Request to %v failed", u.String())
 	}
 }
 
@@ -507,9 +490,6 @@ func (gameState *GameState) buildSnakesFromOptions() map[string]SnakeState {
 	} else {
 		numSnakes = numURLs
 	}
-	if numNames != numURLs {
-		log.Println("[WARN]: Number of Names and URLs do not match: defaults will be applied to missing values")
-	}
 	for i := int(0); i < numSnakes; i++ {
 		var snakeName string
 		var snakeURL string
@@ -519,21 +499,18 @@ func (gameState *GameState) buildSnakesFromOptions() map[string]SnakeState {
 		if i < numNames {
 			snakeName = gameState.Names[i]
 		} else {
-			log.Printf("[WARN]: Name for URL %v is missing: a default name will be applied\n", gameState.URLs[i])
+			log.DEBUG.Printf("Name for URL %v is missing: a name will be generated automatically", gameState.URLs[i])
-			snakeName = id
+			snakeName = GenerateSnakeName()
 		}
 
 		if i < numURLs {
 			u, err := url.ParseRequestURI(gameState.URLs[i])
 			if err != nil {
-				log.Printf("[WARN]: URL %v is not valid: a default will be applied\n", gameState.URLs[i])
+				log.ERROR.Fatalf("URL %v is not valid: %v", gameState.URLs[i], err)
-				snakeURL = "https://example.com"
-			} else {
-				snakeURL = u.String()
 			}
+			snakeURL = u.String()
 		} else {
-			log.Printf("[WARN]: URL for Name %v is missing: a default URL will be applied\n", gameState.Names[i])
+			log.ERROR.Fatalf("URL for name %v is missing", gameState.Names[i])
-			snakeURL = "https://example.com"
 		}
 
 		snakeState := SnakeState{
@@ -542,44 +519,60 @@ func (gameState *GameState) buildSnakesFromOptions() map[string]SnakeState {
 		var snakeErr error
 		res, err := gameState.httpClient.Get(snakeURL)
 		if err != nil {
-			log.Printf("[WARN]: Request to %v failed: %v", snakeURL, err)
+			log.ERROR.Fatalf("Snake metadata request to %v failed: %v", snakeURL, err)
-			snakeErr = err
+		}
-		} else {
+
 		snakeState.StatusCode = res.StatusCode
 
-			if res.Body != nil {
+		if res.Body == nil {
+			log.ERROR.Fatalf("Empty response body from snake metadata URL: %v", snakeURL)
+		}
+
 		defer res.Body.Close()
 		body, readErr := ioutil.ReadAll(res.Body)
 		if readErr != nil {
-					log.Fatal(readErr)
+			log.ERROR.Fatalf("Error reading from snake metadata URL %v: %v", snakeURL, readErr)
 		}
 
 		pingResponse := client.SnakeMetadataResponse{}
 		jsonErr := json.Unmarshal(body, &pingResponse)
 		if jsonErr != nil {
-					snakeErr = jsonErr
+			log.ERROR.Fatalf("Failed to parse response from %v: %v", snakeURL, jsonErr)
-					log.Printf("Error reading response from %v: %v", snakeURL, jsonErr)
+		}
-				} else {
+
 		snakeState.Head = pingResponse.Head
 		snakeState.Tail = pingResponse.Tail
 		snakeState.Color = pingResponse.Color
 		snakeState.Author = pingResponse.Author
 		snakeState.Version = pingResponse.Version
-				}
+
-			}
-		}
 		if snakeErr != nil {
 			snakeState.Error = snakeErr
 		}
 
 		snakes[snakeState.ID] = snakeState
+
+		log.INFO.Printf("Snake ID: %v URL: %v, Name: \"%v\"", snakeState.ID, snakeURL, snakeState.Name)
 	}
 	return snakes
 }
 
+func (gameState *GameState) printState(boardState *rules.BoardState) {
+	var aliveSnakeNames []string
+	for _, snake := range boardState.Snakes {
+		if snake.EliminatedCause == rules.NotEliminated {
+			aliveSnakeNames = append(aliveSnakeNames, gameState.snakeStates[snake.ID].Name)
+		}
+	}
+	log.INFO.Printf(
+		"Turn: %d, Snakes Alive: [%v], Food: %d, Hazards: %d",
+		boardState.Turn, strings.Join(aliveSnakeNames, ", "), len(boardState.Food), len(boardState.Hazards),
+	)
+}
+
 func (gameState *GameState) printMap(boardState *rules.BoardState) {
 	var o bytes.Buffer
-	o.WriteString(fmt.Sprintf("Ruleset: %s, Seed: %d, Turn: %v\n", gameState.GameType, gameState.Seed, boardState.Turn))
+	o.WriteString(fmt.Sprintf("Turn: %d\n", boardState.Turn))
 	board := make([][]string, boardState.Width)
 	for i := range board {
 		board[i] = make([]string, boardState.Height)
@@ -618,21 +611,28 @@ func (gameState *GameState) printMap(boardState *rules.BoardState) {
 		o.WriteString(fmt.Sprintf("Food ⚕: %v\n", boardState.Food))
 	}
 	for _, s := range boardState.Snakes {
-		red, green, blue := parseSnakeColor(gameState.snakeStates[s.ID].Color)
+		state := gameState.snakeStates[s.ID]
+
+		red, green, blue := parseSnakeColor(state.Color)
 		for _, b := range s.Body {
 			if b.X >= 0 && b.X < boardState.Width && b.Y >= 0 && b.Y < boardState.Height {
 				if gameState.UseColor {
 					board[b.X][b.Y] = fmt.Sprintf(TERM_FG_RGB+"■", red, green, blue)
 				} else {
-					board[b.X][b.Y] = string(gameState.snakeStates[s.ID].Character)
+					board[b.X][b.Y] = string(state.Character)
 				}
 			}
 		}
 		if gameState.UseColor {
-			o.WriteString(fmt.Sprintf("%v "+TERM_FG_RGB+TERM_BG_WHITE+"■■■"+TERM_RESET+": %v\n", gameState.snakeStates[s.ID].Name, red, green, blue, s))
+			o.WriteString(fmt.Sprintf("%v "+TERM_FG_RGB+TERM_BG_WHITE+"■■■"+TERM_RESET+": ", state.Name, red, green, blue))
 		} else {
-			o.WriteString(fmt.Sprintf("%v %c: %v\n", gameState.snakeStates[s.ID].Name, gameState.snakeStates[s.ID].Character, s))
+			o.WriteString(fmt.Sprintf("%v %c: ", state.Name, state.Character))
 		}
+		o.WriteString(fmt.Sprintf("Health: %d", s.Health))
+		if s.EliminatedCause != rules.NotEliminated {
+			o.WriteString(fmt.Sprintf(", Eliminated: %v, Turn: %d", s.EliminatedCause, s.EliminatedOnTurn))
+		}
+		o.WriteString("\n")
 	}
 	for y := boardState.Height - 1; y >= 0; y-- {
 		if gameState.UseColor {
@@ -646,7 +646,7 @@ func (gameState *GameState) printMap(boardState *rules.BoardState) {
 		}
 		o.WriteString("\n")
 	}
-	log.Print(o.String())
+	fmt.Println(o.String())
 }
 
 func (gameState *GameState) buildFrameEvent(boardState *rules.BoardState) board.GameEvent {
@@ -705,7 +705,7 @@ func (gameState *GameState) buildFrameEvent(boardState *rules.BoardState) board.
 func serialiseSnakeRequest(snakeRequest client.SnakeRequest) []byte {
 	requestJSON, err := json.Marshal(snakeRequest)
 	if err != nil {
-		log.Fatalf("Error marshalling JSON from State: %v", err)
+		log.ERROR.Fatalf("Error marshalling JSON from State: %v", err)
 	}
 	return requestJSON
 }

cli/commands/play_test.go

@@ -25,7 +25,6 @@ func buildDefaultGameState() *GameState {
 		Seed:                1,
 		TurnDelay:           0,
 		TurnDuration:        0,
-		DebugRequests:       false,
 		Output:              "",
 		FoodSpawnChance:     15,
 		MinimumFood:         1,

cli/commands/root.go

@@ -2,15 +2,18 @@ package commands
 
 import (
 	"fmt"
+	stdlog "log"
 	"os"
 
 	"github.com/spf13/cobra"
 
 	homedir "github.com/mitchellh/go-homedir"
+	log "github.com/spf13/jwalterweatherman"
 	"github.com/spf13/viper"
 )
 
 var cfgFile string
+var verbose bool
 
 var rootCmd = &cobra.Command{
 	Use:   "battlesnake",
@@ -41,7 +44,7 @@ func init() {
 	// will be global for your application.
 
 	rootCmd.PersistentFlags().StringVar(&cfgFile, "config", "", "config file (default is $HOME/.battlesnake.yaml)")
-
+	rootCmd.PersistentFlags().BoolVar(&verbose, "verbose", false, "Enable debug logging")
 }
 
 // initConfig reads in config file and ENV variables if set.
@@ -68,4 +71,13 @@ func initConfig() {
 	if err := viper.ReadInConfig(); err == nil {
 		fmt.Println("Using config file:", viper.ConfigFileUsed())
 	}
+
+	// Setup logging
+	log.SetStdoutOutput(os.Stderr)
+	log.SetFlags(stdlog.Ltime | stdlog.Lmicroseconds)
+	if verbose {
+		log.SetStdoutThreshold(log.LevelDebug)
+	} else {
+		log.SetStdoutThreshold(log.LevelInfo)
+	}
 }

go.mod

@@ -9,6 +9,7 @@ require (
 	github.com/pkg/browser v0.0.0-20210911075715-681adbf594b8
 	github.com/rs/cors v1.8.2
 	github.com/spf13/cobra v1.1.1
+	github.com/spf13/jwalterweatherman v1.1.0
 	github.com/spf13/viper v1.7.1
 	github.com/stretchr/testify v1.4.0
 )
@@ -24,7 +25,6 @@ require (
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/spf13/afero v1.1.2 // indirect
 	github.com/spf13/cast v1.3.0 // indirect
-	github.com/spf13/jwalterweatherman v1.0.0 // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
 	github.com/subosito/gotenv v1.2.0 // indirect
 	golang.org/x/sys v0.0.0-20220422013727-9388b58f7150 // indirect

go.sum

@@ -173,8 +173,9 @@ github.com/spf13/cast v1.3.0 h1:oget//CVOEoFewqQxwr0Ej5yjygnqGkvggSE/gB35Q8=
 github.com/spf13/cast v1.3.0/go.mod h1:Qx5cxh0v+4UWYiBimWS+eyWzqEqokIECu5etghLkUJE=
 github.com/spf13/cobra v1.1.1 h1:KfztREH0tPxJJ+geloSLaAkaPkr4ki2Er5quFV1TDo4=
 github.com/spf13/cobra v1.1.1/go.mod h1:WnodtKOvamDL/PwE2M4iKs8aMDBZ5Q5klgD3qfVJQMI=
-github.com/spf13/jwalterweatherman v1.0.0 h1:XHEdyB+EcvlqZamSM4ZOMGlc93t6AcsBEu9Gc1vn7yk=
 github.com/spf13/jwalterweatherman v1.0.0/go.mod h1:cQK4TGJAtQXfYWX+Ddv3mKDzgVb68N+wFjFa4jdeBTo=
+github.com/spf13/jwalterweatherman v1.1.0 h1:ue6voC5bR5F8YxI5S67j9i582FU4Qvo2bmqnqMYADFk=
+github.com/spf13/jwalterweatherman v1.1.0/go.mod h1:aNWZUN0dPAAO/Ljvb5BEdw96iTZ0EXowPYD95IqWIGo=
 github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=