DEV 1793: Track latency, status codes, and errors from CLI games (#113)

* track latency and status code from CLI games

* actually track errors from snake responses

cli/commands/http.go

@@ -0,0 +1,28 @@
+package commands
+
+import (
+	"io"
+	"net/http"
+	"time"
+)
+
+type TimedHttpClient interface {
+	Get(url string) (*http.Response, time.Duration, error)
+	Post(url string, contentType string, body io.Reader) (*http.Response, time.Duration, error)
+}
+
+type timedHTTPClient struct {
+	*http.Client
+}
+
+func (client timedHTTPClient) Get(url string) (*http.Response, time.Duration, error) {
+	startTime := time.Now()
+	res, err := client.Client.Get(url)
+	return res, time.Since(startTime), err
+}
+
+func (client timedHTTPClient) Post(url string, contentType string, body io.Reader) (*http.Response, time.Duration, error) {
+	startTime := time.Now()
+	res, err := client.Client.Post(url, contentType, body)
+	return res, time.Since(startTime), err
+}

cli/commands/play.go

@@ -38,6 +38,7 @@ type SnakeState struct {
 	Version    string
 	Error      error
 	StatusCode int
+	Latency    time.Duration
 }
 
 type GameState struct {
@@ -67,7 +68,7 @@ type GameState struct {
 	settings    map[string]string
 	snakeStates map[string]SnakeState
 	gameID      string
-	httpClient  http.Client
+	httpClient  TimedHttpClient
 	ruleset     rules.Ruleset
 	gameMap     maps.GameMap
 }
@@ -120,8 +121,10 @@ func (gameState *GameState) initialize() {
 	if gameState.Timeout == 0 {
 		gameState.Timeout = 500
 	}
-	gameState.httpClient = http.Client{
+	gameState.httpClient = timedHTTPClient{
+		&http.Client{
 			Timeout: time.Duration(gameState.Timeout) * time.Millisecond,
+		},
 	}
 
 	// Load game map
@@ -315,7 +318,7 @@ func (gameState *GameState) initializeBoardFromArgs() *rules.BoardState {
 		u, _ := url.ParseRequestURI(snakeState.URL)
 		u.Path = path.Join(u.Path, "start")
 		log.DEBUG.Printf("POST %s: %v", u, string(requestBody))
-		_, err = gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
+		_, _, err = gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
 		if err != nil {
 			log.WARN.Printf("Request to %v failed", u.String())
 		}
@@ -324,18 +327,20 @@ func (gameState *GameState) initializeBoardFromArgs() *rules.BoardState {
 }
 
 func (gameState *GameState) createNextBoardState(boardState *rules.BoardState) *rules.BoardState {
-	var moves []rules.SnakeMove
+	stateUpdates := make(chan SnakeState, len(gameState.snakeStates))
+
 	if gameState.Sequential {
 		for _, snakeState := range gameState.snakeStates {
 			for _, snake := range boardState.Snakes {
 				if snakeState.ID == snake.ID && snake.EliminatedCause == rules.NotEliminated {
-					moves = append(moves, gameState.getMoveForSnake(boardState, snakeState))
+					nextSnakeState := gameState.getSnakeUpdate(boardState, snakeState)
+					stateUpdates <- nextSnakeState
 				}
 			}
 		}
+		close(stateUpdates)
 	} else {
 		var wg sync.WaitGroup
-		c := make(chan rules.SnakeMove, len(gameState.snakeStates))
 
 		for _, snakeState := range gameState.snakeStates {
 			for _, snake := range boardState.Snakes {
@@ -343,24 +348,23 @@ func (gameState *GameState) createNextBoardState(boardState *rules.BoardState) *
 					wg.Add(1)
 					go func(snakeState SnakeState) {
 						defer wg.Done()
-						c <- gameState.getMoveForSnake(boardState, snakeState)
+						nextSnakeState := gameState.getSnakeUpdate(boardState, snakeState)
+						stateUpdates <- nextSnakeState
 					}(snakeState)
 				}
 			}
 		}
 
 		wg.Wait()
-		close(c)
+		close(stateUpdates)
+	}
 
-		for move := range c {
+	var moves []rules.SnakeMove
-			moves = append(moves, move)
+	for snakeState := range stateUpdates {
-		}
+		gameState.snakeStates[snakeState.ID] = snakeState
-	}
+		moves = append(moves, rules.SnakeMove{ID: snakeState.ID, Move: snakeState.LastMove})
-	for _, move := range moves {
-		snakeState := gameState.snakeStates[move.ID]
-		snakeState.LastMove = move.Move
-		gameState.snakeStates[move.ID] = snakeState
 	}
+
 	boardState, err := gameState.ruleset.CreateNextBoardState(boardState, moves)
 	if err != nil {
 		log.ERROR.Fatalf("Error producing next board state: %v", err)
@@ -376,28 +380,41 @@ func (gameState *GameState) createNextBoardState(boardState *rules.BoardState) *
 	return boardState
 }
 
-func (gameState *GameState) getMoveForSnake(boardState *rules.BoardState, snakeState SnakeState) rules.SnakeMove {
+func (gameState *GameState) getSnakeUpdate(boardState *rules.BoardState, snakeState SnakeState) SnakeState {
+	snakeState.StatusCode = 0
+	snakeState.Error = nil
+	snakeState.Latency = 0
+
 	snakeRequest := gameState.getRequestBodyForSnake(boardState, snakeState)
 	requestBody := serialiseSnakeRequest(snakeRequest)
-	u, _ := url.ParseRequestURI(snakeState.URL)
+
+	u, err := url.ParseRequestURI(snakeState.URL)
+	if err != nil {
+		log.ERROR.Printf("Error parsing snake URL %#v: %v", snakeState.URL, err)
+		snakeState.Error = err
+		return snakeState
+	}
 	u.Path = path.Join(u.Path, "move")
 	log.DEBUG.Printf("POST %s: %v", u, string(requestBody))
-	res, err := gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
+	res, responseTime, err := gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
 
-	// Use snake's last move as the default in case of an error
+	snakeState.Latency = responseTime
-	snakeMove := rules.SnakeMove{ID: snakeState.ID, Move: snakeState.LastMove}
 
 	if err != nil {
 		log.WARN.Printf(
 			"Request to %v failed\n"+
 				"\tError: %s", u.String(), err)
-		return snakeMove
+		snakeState.Error = err
+		return snakeState
 	}
+
+	snakeState.StatusCode = res.StatusCode
+
 	if res.Body == nil {
 		log.WARN.Printf(
 			"Failed to parse response from %v\n"+
 				"\tError: body is empty", u.String())
-		return snakeMove
+		return snakeState
 	}
 	defer res.Body.Close()
 	body, readErr := ioutil.ReadAll(res.Body)
@@ -405,15 +422,17 @@ func (gameState *GameState) getMoveForSnake(boardState *rules.BoardState, snakeS
 		log.WARN.Printf(
 			"Failed to read response body from %v\n"+
 				"\tError: %v", u.String(), readErr)
-		return snakeMove
+		snakeState.Error = readErr
+		return snakeState
 	}
 	if res.StatusCode != http.StatusOK {
 		log.WARN.Printf(
 			"Got non-ok status code from %v\n"+
 				"\tStatusCode: %d (expected %d)\n"+
 				"\tBody: %q", u.String(), res.StatusCode, http.StatusOK, body)
-		return snakeMove
+		return snakeState
 	}
+
 	playerResponse := client.MoveResponse{}
 	jsonErr := json.Unmarshal(body, &playerResponse)
 	if jsonErr != nil {
@@ -422,7 +441,8 @@ func (gameState *GameState) getMoveForSnake(boardState *rules.BoardState, snakeS
 				"\tError: %v\n"+
 				"\tBody: %q\n"+
 				"\tSee https://docs.battlesnake.com/references/api#post-move", u.String(), jsonErr, body)
-		return snakeMove
+		snakeState.Error = jsonErr
+		return snakeState
 	}
 	if playerResponse.Move != "up" && playerResponse.Move != "down" && playerResponse.Move != "left" && playerResponse.Move != "right" {
 		log.WARN.Printf(
@@ -430,11 +450,12 @@ func (gameState *GameState) getMoveForSnake(boardState *rules.BoardState, snakeS
 				"\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)
-		return snakeMove
+		return snakeState
 	}
 
-	snakeMove.Move = playerResponse.Move
+	snakeState.LastMove = playerResponse.Move
-	return snakeMove
+
+	return snakeState
 }
 
 func (gameState *GameState) sendEndRequest(boardState *rules.BoardState, snakeState SnakeState) {
@@ -443,7 +464,7 @@ func (gameState *GameState) sendEndRequest(boardState *rules.BoardState, snakeSt
 	u, _ := url.ParseRequestURI(snakeState.URL)
 	u.Path = path.Join(u.Path, "end")
 	log.DEBUG.Printf("POST %s: %v", u, string(requestBody))
-	_, err := gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
+	_, _, err := gameState.httpClient.Post(u.String(), "application/json", bytes.NewBuffer(requestBody))
 	if err != nil {
 		log.WARN.Printf("Request to %v failed", u.String())
 	}
@@ -517,7 +538,7 @@ func (gameState *GameState) buildSnakesFromOptions() map[string]SnakeState {
 			Name: snakeName, URL: snakeURL, ID: id, LastMove: "up", Character: bodyChars[i%8],
 		}
 		var snakeErr error
-		res, err := gameState.httpClient.Get(snakeURL)
+		res, _, err := gameState.httpClient.Get(snakeURL)
 		if err != nil {
 			log.ERROR.Fatalf("Snake metadata request to %v failed: %v", snakeURL, err)
 		}
@@ -655,6 +676,10 @@ func (gameState *GameState) buildFrameEvent(boardState *rules.BoardState) board.
 	for _, snake := range boardState.Snakes {
 		snakeState := gameState.snakeStates[snake.ID]
 
+		latencyMS := snakeState.Latency.Milliseconds()
+		if latencyMS == 0 {
+			latencyMS = 1
+		}
 		convertedSnake := board.Snake{
 			ID:            snake.ID,
 			Name:          snakeState.Name,
@@ -667,9 +692,7 @@ func (gameState *GameState) buildFrameEvent(boardState *rules.BoardState) board.
 			StatusCode:    snakeState.StatusCode,
 			IsBot:         false,
 			IsEnvironment: false,
-
+			Latency:       fmt.Sprint(latencyMS),
-			// Not supporting local latency for now - there are better ways to test performance locally
-			Latency: "1",
 		}
 		if snakeState.Error != nil {
 			// Instead of trying to keep in sync with the production engine's

cli/commands/play_test.go

@@ -1,8 +1,14 @@
 package commands
 
 import (
+	"bytes"
+	"errors"
 	"fmt"
+	"io"
+	"io/ioutil"
+	"net/http"
 	"testing"
+	"time"
 
 	"github.com/BattlesnakeOfficial/rules"
 	"github.com/BattlesnakeOfficial/rules/board"
@@ -279,6 +285,7 @@ func TestBuildFrameEvent(t *testing.T) {
 					Version:    "1.5",
 					Error:      nil,
 					StatusCode: 200,
+					Latency:    54 * time.Millisecond,
 				},
 			},
 			expected: board.GameEvent{
@@ -300,7 +307,7 @@ func TestBuildFrameEvent(t *testing.T) {
 							Color:         "#ff00ff",
 							HeadType:      "silly",
 							TailType:      "default",
-							Latency:       "1",
+							Latency:       "54",
 							Author:        "AUTHOR",
 							StatusCode:    200,
 							Error:         "",
@@ -330,9 +337,11 @@ func TestBuildFrameEvent(t *testing.T) {
 			snakeStates: map[string]SnakeState{
 				"bad_status": {
 					StatusCode: 504,
+					Latency:    54 * time.Millisecond,
 				},
 				"connection_error": {
 					Error:   fmt.Errorf("error connecting to host"),
+					Latency: 0,
 				},
 			},
 			expected: board.GameEvent{
@@ -342,7 +351,7 @@ func TestBuildFrameEvent(t *testing.T) {
 					Snakes: []board.Snake{
 						{
 							ID:         "bad_status",
-							Latency:    "1",
+							Latency:    "54",
 							StatusCode: 504,
 							Error:      "7:Bad HTTP status code 504",
 						},
@@ -367,3 +376,212 @@ func TestBuildFrameEvent(t *testing.T) {
 		})
 	}
 }
+
+func TestGetMoveForSnake(t *testing.T) {
+	s1 := rules.Snake{ID: "one", Body: []rules.Point{{X: 3, Y: 3}}}
+	s2 := rules.Snake{ID: "two", Body: []rules.Point{{X: 4, Y: 3}}}
+	boardState := &rules.BoardState{
+		Height: 11,
+		Width:  11,
+		Snakes: []rules.Snake{s1, s2},
+	}
+
+	tests := []struct {
+		name            string
+		boardState      *rules.BoardState
+		snakeState      SnakeState
+		responseErr     error
+		responseCode    int
+		responseBody    string
+		responseLatency time.Duration
+
+		expectedSnakeState SnakeState
+	}{
+		{
+			name:       "invalid URL",
+			boardState: boardState,
+			snakeState: SnakeState{
+				ID:       "one",
+				URL:      "",
+				LastMove: rules.MoveLeft,
+			},
+			expectedSnakeState: SnakeState{
+				ID:       "one",
+				URL:      "",
+				LastMove: rules.MoveLeft,
+				Error:    errors.New(`parse "": empty url`),
+			},
+		},
+		{
+			name:       "error response",
+			boardState: boardState,
+			snakeState: SnakeState{
+				ID:       "one",
+				URL:      "http://example.com",
+				LastMove: rules.MoveLeft,
+			},
+			responseErr: errors.New("connection error"),
+			expectedSnakeState: SnakeState{
+				ID:       "one",
+				URL:      "http://example.com",
+				LastMove: rules.MoveLeft,
+				Error:    errors.New("connection error"),
+			},
+		},
+		{
+			name:       "bad response body",
+			boardState: boardState,
+			snakeState: SnakeState{
+				ID:       "one",
+				URL:      "http://example.com",
+				LastMove: rules.MoveLeft,
+			},
+			responseCode:    200,
+			responseBody:    `right`,
+			responseLatency: 54 * time.Millisecond,
+			expectedSnakeState: SnakeState{
+				ID:         "one",
+				URL:        "http://example.com",
+				LastMove:   rules.MoveLeft,
+				Error:      errors.New("invalid character 'r' looking for beginning of value"),
+				StatusCode: 200,
+				Latency:    54 * time.Millisecond,
+			},
+		},
+		{
+			name:       "bad move value",
+			boardState: boardState,
+			snakeState: SnakeState{
+				ID:       "one",
+				URL:      "http://example.com",
+				LastMove: rules.MoveLeft,
+			},
+			responseCode:    200,
+			responseBody:    `{"move": "north"}`,
+			responseLatency: 54 * time.Millisecond,
+			expectedSnakeState: SnakeState{
+				ID:         "one",
+				URL:        "http://example.com",
+				LastMove:   rules.MoveLeft,
+				StatusCode: 200,
+				Latency:    54 * time.Millisecond,
+			},
+		},
+		{
+			name:       "bad status code",
+			boardState: boardState,
+			snakeState: SnakeState{
+				ID:       "one",
+				URL:      "http://example.com",
+				LastMove: rules.MoveLeft,
+			},
+			responseCode:    500,
+			responseLatency: 54 * time.Millisecond,
+			expectedSnakeState: SnakeState{
+				ID:         "one",
+				URL:        "http://example.com",
+				LastMove:   rules.MoveLeft,
+				StatusCode: 500,
+				Latency:    54 * time.Millisecond,
+			},
+		},
+		{
+			name:       "successful move",
+			boardState: boardState,
+			snakeState: SnakeState{
+				ID:  "one",
+				URL: "http://example.com",
+			},
+			responseCode:    200,
+			responseBody:    `{"move": "right"}`,
+			responseLatency: 54 * time.Millisecond,
+			expectedSnakeState: SnakeState{
+				ID:         "one",
+				URL:        "http://example.com",
+				LastMove:   rules.MoveRight,
+				StatusCode: 200,
+				Latency:    54 * time.Millisecond,
+			},
+		},
+	}
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			gameState := buildDefaultGameState()
+			gameState.initialize()
+			gameState.snakeStates = map[string]SnakeState{test.snakeState.ID: test.snakeState}
+			gameState.httpClient = stubHTTPClient{test.responseErr, test.responseCode, test.responseBody, test.responseLatency}
+
+			nextSnakeState := gameState.getSnakeUpdate(test.boardState, test.snakeState)
+			if test.expectedSnakeState.Error != nil {
+				require.EqualError(t, nextSnakeState.Error, test.expectedSnakeState.Error.Error())
+			} else {
+				require.NoError(t, nextSnakeState.Error)
+			}
+			nextSnakeState.Error = test.expectedSnakeState.Error
+			require.Equal(t, test.expectedSnakeState, nextSnakeState)
+		})
+	}
+}
+
+func TestCreateNextBoardState(t *testing.T) {
+	s1 := rules.Snake{ID: "one", Body: []rules.Point{{X: 3, Y: 3}}}
+	boardState := &rules.BoardState{
+		Height: 11,
+		Width:  11,
+		Snakes: []rules.Snake{s1},
+	}
+	snakeState := SnakeState{
+		ID:  s1.ID,
+		URL: "http://example.com",
+	}
+
+	for _, sequential := range []bool{false, true} {
+		t.Run(fmt.Sprintf("sequential_%v", sequential), func(t *testing.T) {
+			gameState := buildDefaultGameState()
+			gameState.Sequential = sequential
+			gameState.initialize()
+			gameState.snakeStates = map[string]SnakeState{s1.ID: snakeState}
+			gameState.httpClient = stubHTTPClient{nil, 200, `{"move": "right"}`, 54 * time.Millisecond}
+
+			nextBoardState := gameState.createNextBoardState(boardState)
+			snakeState = gameState.snakeStates[s1.ID]
+
+			require.NotNil(t, nextBoardState)
+			require.Equal(t, nextBoardState.Turn, 1)
+			require.Equal(t, nextBoardState.Snakes[0].Body[0], rules.Point{X: 4, Y: 3})
+			require.Equal(t, snakeState.LastMove, rules.MoveRight)
+			require.Equal(t, snakeState.StatusCode, 200)
+			require.Equal(t, snakeState.Latency, 54*time.Millisecond)
+		})
+	}
+}
+
+type stubHTTPClient struct {
+	err        error
+	statusCode int
+	body       string
+	latency    time.Duration
+}
+
+func (client stubHTTPClient) request() (*http.Response, time.Duration, error) {
+	if client.err != nil {
+		return nil, client.latency, client.err
+	}
+	body := ioutil.NopCloser(bytes.NewBufferString(client.body))
+
+	response := &http.Response{
+		Header:     make(http.Header),
+		Body:       body,
+		StatusCode: client.statusCode,
+	}
+
+	return response, client.latency, nil
+}
+
+func (client stubHTTPClient) Get(url string) (*http.Response, time.Duration, error) {
+	return client.request()
+}
+
+func (client stubHTTPClient) Post(url string, contentType string, body io.Reader) (*http.Response, time.Duration, error) {
+	return client.request()
+}