From 19e4aee454601e9a317db9518482ceeeac39f566 Mon Sep 17 00:00:00 2001 From: Daniel Dolezal Date: Fri, 3 Apr 2026 18:26:31 +0200 Subject: [PATCH] rework logging and add metrics and prometheus metrics --- server/Server.py | 183 ++++++++++++++++++++++++++++++++++++----------- 1 file changed, 143 insertions(+), 40 deletions(-) diff --git a/server/Server.py b/server/Server.py index 1b2ec25..21191e0 100644 --- a/server/Server.py +++ b/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", - "author": "", - "color": "#888888", - "head": "default", - "tail": "default", + 'apiversion': '1', + 'author': '', + 'color': '#888888', + 'head': '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"]) - return "ok" + await await_log(self.logger.info(f'GAME START: {game_state['game']}')) + 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( - "server", "battlesnake/gitea/snake-python" - ) + response.headers.set('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): - logging.getLogger("werkzeug").setLevel(logging.ERROR) + @self.app.get('/metrics') + 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.run(host=host, port=port, debug=debug) + @self.app.get('/metrics/prometheus') + 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): - snake_config = await read_file(self.config_file, json.load) + async def run(self, host:str='0.0.0.0', port:int=8000, debug:bool=False): + 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]: - for key in ("author", "color", "head", "tail"): - value = os.environ.get(f"SNAKE_{key.upper()}") + async def _override_snake_config_with_environment_variables(self, config:dict[str, str]) -> dict[str, str]: + for key in ('author', 'color', 'head', 'tail'): + 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): - del self.running_games[game_state["game"]["id"]] + def _delete_game_board(self, game_state:dict): + 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'