From 746b30dbebc904d39ca78733782bbdaf175349d3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Maximilian=20Ke=C3=9Fler?= Date: Sat, 20 May 2023 14:32:42 +0200 Subject: [PATCH] rework logging to log into separate files --- check_game.py | 29 ++++++++++++----- hanabi_suite.py | 15 ++++++--- log_setup/__init__.py | 5 +-- log_setup/logger_setup.py | 68 +++++++++++++++++++++++++++++++-------- sat.py | 21 ++++++------ 5 files changed, 99 insertions(+), 39 deletions(-) diff --git a/check_game.py b/check_game.py index dcde7c9..1a3fb49 100644 --- a/check_game.py +++ b/check_game.py @@ -1,21 +1,26 @@ import copy from typing import Tuple, Optional +import verboselogs + from database.database import conn from compress import decompress_deck, decompress_actions, compress_actions, link from hanabi import Action, GameState from hanab_live import HanabLiveInstance, HanabLiveGameState from sat import solve_sat +from log_setup import logger, logger_manager from download_data import detailed_export_game -# returns number of first turn before which the game was infeasible (counting from 0) -# and a replay achieving maximum score (from this turn onwards) if instance is feasible -# 0 if instance is infeasible -# 1 if instance is feasible but first turn is suboptimal +# returns minimal number T of turns (from game) after which instance was infeasible +# and a replay achieving maximum score while following the replay for the first (T-1) turns: +# if instance is feasible, returns number of turns + 1 +# returns 0 if instance is infeasible +# returns 1 if instance is feasible but first turn is suboptimal # ... -# (number of turns) if replay was winning +# # turns + 1 if the final state is still winning def check_game(game_id: int) -> Tuple[int, GameState]: + logger.debug("Analysing game {}".format(game_id)) with conn.cursor() as cur: cur.execute("SELECT games.num_players, deck, actions, score, games.variant_id FROM games " "INNER JOIN seeds ON seeds.seed = games.seed " @@ -32,10 +37,13 @@ def check_game(game_id: int) -> Tuple[int, GameState]: instance = HanabLiveInstance(deck, num_players, variant_id=variant_id) if instance.max_score == score: + game = HanabLiveGameState(instance) + for action in actions: + game.make_action(action) # instance has been won, nothing to compute here - return len(actions) + return len(actions) + 1, game - # store the turn numbers *before* we know the game was (in)feasible + # store lower and upper bounds of numbers of turns after which we know the game was feasible / infeasible solvable_turn = 0 unsolvable_turn = len(actions) @@ -43,7 +51,9 @@ def check_game(game_id: int) -> Tuple[int, GameState]: game = HanabLiveGameState(instance) solvable, solution = solve_sat(game) if not solvable: + logger.debug("Returning: Instance {} is not feasible") return 0, solution + logger.verbose("Instance {} is feasible after 0 turns: {}".format(game_id, link(solution))) while unsolvable_turn - solvable_turn > 1: try_turn = (unsolvable_turn + solvable_turn) // 2 @@ -51,13 +61,16 @@ def check_game(game_id: int) -> Tuple[int, GameState]: assert(len(try_game.actions) == solvable_turn) for a in range(solvable_turn, try_turn): try_game.make_action(actions[a]) + logger.debug("Checking if instance {} is feasible after {} turs".format(game_id, try_turn)) solvable, potential_sol = solve_sat(try_game) if solvable: solution = potential_sol game = try_game solvable_turn = try_turn + logger.verbose("Instance {} is feasible after {} turns: {}".format(game_id, solvable_turn, link(solution))) else: unsolvable_turn = try_turn + logger.verbose("Instance {} is not feasible after {} turns".format(game_id, unsolvable_turn)) - assert(unsolvable_turn - 1 == solvable_turn) + assert unsolvable_turn - 1 == solvable_turn, "Programming error" return unsolvable_turn, solution diff --git a/hanabi_suite.py b/hanabi_suite.py index 694d0e2..d8dc555 100755 --- a/hanabi_suite.py +++ b/hanabi_suite.py @@ -1,10 +1,14 @@ #! /usr/bin/python3 import argparse +import logging + +import verboselogs from check_game import check_game from download_data import detailed_export_game from compress import link +from log_setup import logger, logger_manager """ init db + populate tables @@ -37,14 +41,15 @@ def add_analyze_subparser(subparsers): def analyze_game(game_id: int, download: bool = False): if download: detailed_export_game(game_id) - print('Analyzing game {}'.format(game_id)) + logger.info('Analyzing game {}'.format(game_id)) turn, sol = check_game(game_id) if turn == 0: - print('Instance is unfeasible') + logger.info('Instance is unfeasible') else: - print( - 'Last winning turn was {}.\n' - 'A replay achieving perfect score is: {}'.format(turn, link(sol)) + logger.info('Game was first lost after {} turns.'.format(turn)) + logger.info( + 'A replay achieving perfect score from the previous turn onwards is: {}#{}' + .format(link(sol), turn) ) diff --git a/log_setup/__init__.py b/log_setup/__init__.py index fb1f12a..34da869 100644 --- a/log_setup/__init__.py +++ b/log_setup/__init__.py @@ -1,3 +1,4 @@ -from .logger_setup import make_logger +from .logger_setup import LoggerManager -logger = make_logger() +logger_manager = LoggerManager() +logger = logger_manager.get_logger() diff --git a/log_setup/logger_setup.py b/log_setup/logger_setup.py index ec615aa..f643f5e 100644 --- a/log_setup/logger_setup.py +++ b/log_setup/logger_setup.py @@ -1,20 +1,60 @@ -import logging, verboselogs +import logging +import verboselogs -def make_logger(): - logger = verboselogs.VerboseLogger("hanab-suite") +class LoggerManager: + def __init__(self, console_level: int = logging.INFO): + self.logger = verboselogs.VerboseLogger("hanab-suite") - logger.setLevel(logging.DEBUG) + self.logger.setLevel(logging.DEBUG) - f_handler = logging.FileHandler("a_log.txt") - f_formatter = logging.Formatter( - '[%(asctime)s] [%(name)s] [%(levelname)s]: %(message)s' - ) - f_handler.setFormatter(f_formatter) - logger.addHandler(f_handler) + self.file_formatter = logging.Formatter( + '[%(asctime)s] [PID %(process)s] [%(levelname)7s]: %(message)s' + ) - console_handler = logging.StreamHandler() - console_handler.setLevel(logging.INFO) - logger.addHandler(console_handler) + self.info_file_formatter = logging.Formatter( + '[%(asctime)s] [PID %(process)s]: %(message)s' + ) - return logger + self.console_formatter = logging.Formatter( + '[%(levelname)7s]: %(message)s' + ) + + self.nothing_formatter = logging.Formatter( + '%(message)s' + ) + + + self.console_handler = logging.StreamHandler() + self.console_handler.setLevel(console_level) + self.console_handler.setFormatter(self.nothing_formatter) + + self.debug_file_handler = logging.FileHandler("debug_log.txt") + self.debug_file_handler.setFormatter(self.file_formatter) + self.debug_file_handler.setLevel(logging.DEBUG) + + self.verbose_file_handler = logging.FileHandler("verbose_log.txt") + self.verbose_file_handler.setFormatter(self.file_formatter) + self.verbose_file_handler.setLevel(verboselogs.VERBOSE) + + self.info_file_handler = logging.FileHandler("log.txt") + self.info_file_handler.setFormatter(self.info_file_formatter) + self.info_file_handler.setLevel(logging.INFO) + + self.logger.addHandler(self.console_handler) + self.logger.addHandler(self.debug_file_handler) + self.logger.addHandler(self.verbose_file_handler) + self.logger.addHandler(self.info_file_handler) + + def set_console_level(self, level: int): + self.console_handler.setLevel(level) + if level == logging.INFO: + self.console_handler.setFormatter(self.nothing_formatter) + else: + self.console_handler.setFormatter(self.console_formatter) + + def is_console_level_active(self, level: int): + return level >= self.console_handler.level + + def get_logger(self): + return self.logger diff --git a/sat.py b/sat.py index 7a4581a..462f988 100644 --- a/sat.py +++ b/sat.py @@ -9,6 +9,7 @@ from hanabi import DeckCard, Action, ActionType, GameState, HanabiInstance from compress import link, decompress_deck from greedy_solver import GreedyStrategy from constants import COLOR_INITIALS +from log_setup import logger # literals to model game as sat instance to check for feasibility @@ -304,7 +305,7 @@ def solve_sat(starting_state: GameState | HanabiInstance) -> Tuple[bool, Optiona model = get_model(constraints) if model: - print_model(model, game_state, ls) + log_model(model, game_state, ls) solution = evaluate_model(model, copy.deepcopy(game_state), ls) return True, solution else: @@ -317,21 +318,21 @@ def solve_sat(starting_state: GameState | HanabiInstance) -> Tuple[bool, Optiona return False, None -def print_model(model, cur_game_state, ls: Literals): +def log_model(model, cur_game_state, ls: Literals): deck = cur_game_state.deck first_turn = len(cur_game_state.actions) if first_turn > 0: - print('[print_model] Note: Omitting first {} turns, since they were fixed already.'.format(first_turn)) + logger.debug('[print_model] Note: Omitting first {} turns, since they were fixed already.'.format(first_turn)) for m in range(first_turn, cur_game_state.instance.max_winning_moves): - print('=== move {} ==='.format(m)) - print('clues: ' + ''.join(str(i) for i in range(1, 9) if model.get_py_value(ls.clues[m][i]))) - print('strikes: ' + ''.join(str(i) for i in range(1, 3) if model.get_py_value(ls.strikes[m][i]))) - print('draw: ' + ', '.join('{}: {}'.format(i, deck[i]) for i in range(cur_game_state.progress, cur_game_state.instance.deck_size) if model.get_py_value(ls.draw[m][i]))) - print('discard: ' + ', '.join('{}: {}'.format(i, deck[i]) for i in range(cur_game_state.instance.deck_size) if model.get_py_value(ls.discard[m][i]))) + logger.debug('=== move {} ==='.format(m)) + logger.debug('clues: ' + ''.join(str(i) for i in range(1, 9) if model.get_py_value(ls.clues[m][i]))) + logger.debug('strikes: ' + ''.join(str(i) for i in range(1, 3) if model.get_py_value(ls.strikes[m][i]))) + logger.debug('draw: ' + ', '.join('{}: {}'.format(i, deck[i]) for i in range(cur_game_state.progress, cur_game_state.instance.deck_size) if model.get_py_value(ls.draw[m][i]))) + logger.debug('discard: ' + ', '.join('{}: {}'.format(i, deck[i]) for i in range(cur_game_state.instance.deck_size) if model.get_py_value(ls.discard[m][i]))) for s in range(0, cur_game_state.instance.num_suits): - print('progress {}: '.format(COLOR_INITIALS[s]) + ''.join(str(r) for r in range(1, 6) if model.get_py_value(ls.progress[m][s, r]))) + logger.debug('progress {}: '.format(COLOR_INITIALS[s]) + ''.join(str(r) for r in range(1, 6) if model.get_py_value(ls.progress[m][s, r]))) flags = ['discard_any', 'draw_any', 'play', 'play5', 'incr_clues', 'strike', 'extraround', 'dummyturn'] - print(', '.join(f for f in flags if model.get_py_value(getattr(ls, f)[m]))) + logger.debug(', '.join(f for f in flags if model.get_py_value(getattr(ls, f)[m])))