rework logging to log into separate files

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)
+# returns minimal number T of turns (from game) after which instance was infeasible
-# and a replay achieving maximum score (from this turn onwards) if instance is feasible
+# and a replay achieving maximum score while following the replay for the first (T-1) turns:
-# 0 if instance is infeasible
+# if instance is feasible, returns number of turns + 1
-# 1 if instance is feasible but first turn is suboptimal
+# 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

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(
+        logger.info('Game was first lost after {} turns.'.format(turn))
-            'Last winning turn was {}.\n'
+        logger.info(
-            'A replay achieving perfect score is: {}'.format(turn, link(sol))
+            'A replay achieving perfect score from the previous turn onwards is: {}#{}'
+            .format(link(sol), turn)
         )
 
 

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()

log_setup/logger_setup.py

@@ -1,20 +1,60 @@
-import logging, verboselogs
+import logging
+import verboselogs
 
 
-def make_logger():
+class LoggerManager:
-    logger = verboselogs.VerboseLogger("hanab-suite")
+    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")
+        self.file_formatter = logging.Formatter(
-    f_formatter = logging.Formatter(
+            '[%(asctime)s] [PID %(process)s] [%(levelname)7s]: %(message)s'
-        '[%(asctime)s] [%(name)s] [%(levelname)s]: %(message)s'
+        )
-    )
-    f_handler.setFormatter(f_formatter)
-    logger.addHandler(f_handler)
 
-    console_handler = logging.StreamHandler()
+        self.info_file_formatter = logging.Formatter(
-    console_handler.setLevel(logging.INFO)
+            '[%(asctime)s] [PID %(process)s]: %(message)s'
-    logger.addHandler(console_handler)
+        )
 
-    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

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))
+        logger.debug('=== move {} ==='.format(m))
-        print('clues: ' + ''.join(str(i) for i in range(1, 9) if model.get_py_value(ls.clues[m][i])))
+        logger.debug('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])))
+        logger.debug('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])))
+        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])))
-        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('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])))