rework logging and add metrics and prometheus metrics

server/Server.py

@@ -1,6 +1,9 @@
 from server.Files import read_file
 from server.GameBoard import GameBoard
 from server.SnakeBuilder import SnakeBuilder
+from quart_common.web.logger import await_log
+from quart_common.web.logger import build_logger
+from typing import cast
 
 from server.storage.StorageLoader import StorageLoader
 
@@ -9,11 +12,11 @@ import logging, json, os, re
 
 class Server:
   default_snake_config = {
-    "apiversion": "1",
+    'apiversion': '1',
-    "author": "",
+    'author': '',
-    "color": "#888888",
+    'color': '#888888',
-    "head": "default",
+    'head': 'default',
-    "tail": "default",
+    'tail': 'default',
   }
 
   def __init__(self, data_path:str, snake_type:str, storage_type:str, debug:bool=False, check_tls_security:bool=False):
@@ -28,41 +31,52 @@ class Server:
     self.store_game_state = False
 
     self.running_games:dict[str, GameBoard] = {}
+    self.game_move_counts:dict[str, int] = {}
+    self.metrics = {
+      'games_started': 0,
+      'games_ended': 0,
+      'wins': 0,
+      'losses': 0,
+      'total_moves': 0,
+      'total_turns': 0,
+      'max_turn': 0,
+    }
+    self.logger = build_logger('Battlesnake', debug_env_var='DEBUG_SERVER')
 
-    self.app = Quart("Battlesnake")
+    self.app = Quart('Battlesnake')
 
     # info is called when you create your Battlesnake on play.battlesnake.com
     # and controls your Battlesnake's appearance
     # TIP: If you open your Battlesnake URL in a browser you should see this data
-    @self.app.get("/")
+    @self.app.get('/')
     async def on_info():
       snake_config = await self._read_json_config_or_create()
 
-      print("INFO Snake:", snake_config)
+      await await_log(self.logger.info(f'INFO Snake: {snake_config}'))
       return snake_config
 
     # start is called when your Battlesnake begins a game
-    @self.app.post("/start")
+    @self.app.post('/start')
     async def on_start():
       game_state = await request.get_json()
       await self._create_game_board(game_state)
-      print("GAME START:", game_state["game"])
+      await await_log(self.logger.info(f'GAME START: {game_state['game']}'))
-      return "ok"
+      return 'ok'
 
     # move is called when your Battlesnake game is running game
-    @self.app.post("/move")
+    @self.app.post('/move')
     async def on_move():
       game_state = await request.get_json()
       game_board = await self._get_game_board(game_state)
       next_move = game_board.snake_neat_make_a_move()
 
       if self.debug:
-        print("TURN:", f'{game_state["turn"]:3},', "MOVE:", f"{next_move:5}")
+        await await_log(self.logger.debug(f'TURN: {game_state['turn']:3}, MOVE: {next_move:5}'))
 
-      return {"move": next_move}
+      return {'move': next_move}
 
     # end is called when your Battlesnake finishes a game
-    @self.app.post("/end")
+    @self.app.post('/end')
     async def on_end():
       game_state = await request.get_json()
       if self.store_game_state:
@@ -71,77 +85,98 @@ class Server:
           await game_board.save(
             StorageLoader.build(self.storage_type),
             file_path=os.path.join(self.data_path, 'data'),
-            database=os.getenv("EDGEDB_DATABASE", None),
+            database=os.getenv('EDGEDB_DATABASE', None),
             tls_security=None
           )
         else:
           await game_board.save(
             StorageLoader.build(self.storage_type),
             file_path=os.path.join(self.data_path, 'data'),
-            database=os.getenv("EDGEDB_DATABASE", None),
+            database=os.getenv('EDGEDB_DATABASE', None),
           )
 
-      print("GAME ENDED: Winner is", [ x["name"] for x in game_state["board"]['snakes']])
+      await await_log(self.logger.info(f'GAME ENDED: Winner is {[x['name'] for x in game_state['board']['snakes']]}'))
       self._delete_game_board(game_state)
-      return "ok"
+      return 'ok'
 
     @self.app.after_request
     async def identify_server(response):
-      response.headers.set(
+      response.headers.set('server', 'battlesnake/gitea/snake-python')
-        "server", "battlesnake/gitea/snake-python"
-      )
       return response
 
-    @self.app.get("/cleanup")
+    @self.app.get('/cleanup')
     async def cleanup():
       results = self._cleanup_database()
       return jsonify(data=json.loads(results), status=200)
 
-  def run(self, host:str="0.0.0.0", port:str="8000", debug:bool=False):
+    @self.app.get('/metrics')
-    logging.getLogger("werkzeug").setLevel(logging.ERROR)
+    async def metrics():
+      return jsonify(self._build_metrics())
 
-    print(f"\nRunning Battlesnake at http://{host}:{port} with the {' '.join(re.findall('[A-Z][^A-Z]*', self.snake_type))}")
+    @self.app.get('/metrics/prometheus')
-    self.app.run(host=host, port=port, debug=debug)
+    async def metrics_prometheus():
+      return (
+        self._build_prometheus_metrics(),
+        200,
+        {'Content-Type': 'text/plain; version=0.0.4; charset=utf-8'},
+      )
 
-  async def _read_json_config_or_create(self):
+  async def run(self, host:str='0.0.0.0', port:int=8000, debug:bool=False):
-    snake_config = await read_file(self.config_file, json.load)
+    logging.getLogger('werkzeug').setLevel(logging.ERROR)
+
+    await await_log(self.logger.info(f'Running Battlesnake at http://{host}:{port} with the {" ".join(re.findall("[A-Z][^A-Z]*", self.snake_type))}'))
+    await self.app.run_task(host=host, port=port, debug=debug)
+
+  async def _read_json_config_or_create(self) -> dict[str, str]:
+    snake_config = cast(dict[str, str]|None, await read_file(self.config_file, json.load))
     if not snake_config:
       return await self._override_snake_config_with_environment_variables(self.default_snake_config)
     return await self._override_snake_config_with_environment_variables(snake_config)
 
-  async def _override_snake_config_with_environment_variables(self, config: dict[str, str]) -> dict[str, str]:
+  async def _override_snake_config_with_environment_variables(self, config:dict[str, str]) -> dict[str, str]:
-    for key in ("author", "color", "head", "tail"):
+    for key in ('author', 'color', 'head', 'tail'):
-      value = os.environ.get(f"SNAKE_{key.upper()}")
+      value = os.environ.get(f'SNAKE_{key.upper()}')
       if value is not None:
         config[key] = value
     return config
 
   async def _create_game_board(self, game_state:dict):
+    game_id = game_state['game']['id']
     new_game_board = GameBoard(
-      game_id=game_state["game"]["id"],
+      game_id=game_id,
       width=game_state['board']['width'],
       height=game_state['board']['height'],
-      ruleset=game_state['game']["ruleset"],
+      ruleset=game_state['game']['ruleset'],
       source=game_state['game']['source'],
       map=game_state['game']['map'],
-      snake_class=SnakeBuilder.build(self.snake_type)
+      snake_class=SnakeBuilder.build(self.snake_type),
     )
     await new_game_board.start_game(game_state)
 
-    self.running_games[game_state["game"]["id"]] = new_game_board
+    self.running_games[game_id] = new_game_board
+    self.game_move_counts[game_id] = 0
+    self.metrics['games_started'] += 1
     return new_game_board
 
-  def _delete_game_board(self, game_state):
+  def _delete_game_board(self, game_state:dict):
-    del self.running_games[game_state["game"]["id"]]
+    game_id = game_state['game']['id']
+    del self.running_games[game_id]
+    self.game_move_counts.pop(game_id, None)
 
-  async def _get_game_board(self, game_state:str, end:bool=False):
+  async def _get_game_board(self, game_state:dict, end:bool=False):
+    game_id = game_state['game']['id']
     try:
-      game_board = self.running_games[game_state["game"]["id"]]
+      game_board = self.running_games[game_id]
     except KeyError:
       game_board = await self._create_game_board(game_state)
 
+    if not end:
+      self.metrics['total_moves'] += 1
+      self.game_move_counts[game_id] = self.game_move_counts.get(game_id, 0) + 1
+
     game_board.read_game_data(game_state)
     if end:
+      self._record_game_end(game_state)
       game_board.end_game(game_state)
 
     return game_board
@@ -152,3 +187,71 @@ class Server:
   def _cleanup_database(self):
     storage = StorageLoader.build(self.storage_type)()
     return storage.cleanup()
+
+  def _record_game_end(self, game_state: dict):
+    self.metrics['games_ended'] += 1
+
+    final_turn = int(game_state.get('turn', 0))
+    self.metrics['total_turns'] += final_turn
+    self.metrics['max_turn'] = max(self.metrics['max_turn'], final_turn)
+
+    you_id = game_state.get('you', {}).get('id')
+    alive_snakes = game_state.get('board', {}).get('snakes', [])
+    alive_ids = {snake.get('id') for snake in alive_snakes}
+
+    if you_id and you_id in alive_ids:
+      self.metrics['wins'] += 1
+    else:
+      self.metrics['losses'] += 1
+
+  def _build_metrics(self) -> dict:
+    games_ended = self.metrics['games_ended']
+    avg_turns = self.metrics['total_turns'] / games_ended if games_ended else 0.0
+    win_rate = self.metrics['wins'] / games_ended if games_ended else 0.0
+
+    return {
+      **self.metrics,
+      'active_games': len(self.running_games),
+      'tracked_games': len(self.game_move_counts),
+      'avg_turns_per_game': round(avg_turns, 2),
+      'win_rate': round(win_rate, 4),
+    }
+
+  def _build_prometheus_metrics(self) -> str:
+    snapshot = self._build_metrics()
+    lines = [
+      '# HELP snake_games_started_total Total games started by snake server.',
+      '# TYPE snake_games_started_total counter',
+      f'snake_games_started_total {snapshot['games_started']}',
+      '# HELP snake_games_ended_total Total games ended by snake server.',
+      '# TYPE snake_games_ended_total counter',
+      f'snake_games_ended_total {snapshot['games_ended']}',
+      '# HELP snake_wins_total Total games won by this snake.',
+      '# TYPE snake_wins_total counter',
+      f'snake_wins_total {snapshot['wins']}',
+      '# HELP snake_losses_total Total games lost by this snake.',
+      '# TYPE snake_losses_total counter',
+      f'snake_losses_total {snapshot['losses']}',
+      '# HELP snake_moves_total Total move decisions served by /move.',
+      '# TYPE snake_moves_total counter',
+      f'snake_moves_total {snapshot['total_moves']}',
+      '# HELP snake_turns_total Total turns across all ended games.',
+      '# TYPE snake_turns_total counter',
+      f'snake_turns_total {snapshot['total_turns']}',
+      '# HELP snake_active_games Currently active games in memory.',
+      '# TYPE snake_active_games gauge',
+      f'snake_active_games {snapshot['active_games']}',
+      '# HELP snake_tracked_games Currently tracked game IDs for move counters.',
+      '# TYPE snake_tracked_games gauge',
+      f'snake_tracked_games {snapshot['tracked_games']}',
+      '# HELP snake_max_turn Highest final turn seen in an ended game.',
+      '# TYPE snake_max_turn gauge',
+      f'snake_max_turn {snapshot['max_turn']}',
+      '# HELP snake_avg_turns_per_game Average final turn per ended game.',
+      '# TYPE snake_avg_turns_per_game gauge',
+      f'snake_avg_turns_per_game {snapshot['avg_turns_per_game']}',
+      '# HELP snake_win_rate Win ratio from ended games (0.0 - 1.0).',
+      '# TYPE snake_win_rate gauge',
+      f'snake_win_rate {snapshot['win_rate']}',
+    ]
+    return '\n'.join(lines) + '\n'