improve overall logging, use verbose logger

database/init_database.py

@@ -1,17 +1,22 @@
 import json
 import requests
 from pathlib import Path
+from log_setup import logger
 
 from .database import cur, conn
 
 
 def init_database_tables():
     this = Path(__file__)
+    logger.verbose("Initialising games and seeds tables...")
     with open(this.parent / "games_seeds_schema.sql") as f:
         cur.execute(f.read())
+    logger.verbose("Successfully initialised games and seeds tables.")
 
+    logger.verbose("Initialising variants, colors and suits tables...")
     with open(this.parent / "variant_suits_schema.sql", "r") as f:
         cur.execute(f.read())
+    logger.verbose("Successfully initialised variants, colors and suits tables...")
 
     conn.commit()
 
@@ -21,6 +26,7 @@ def populate_static_tables():
 
 
 def _populate_static_tables(suits, variants):
+    logger.verbose("Populating static tables with hanab.live format information")
     suits_to_reverse = set()
     for var in variants:
         for suit in var['suits']:
@@ -34,6 +40,8 @@ def _populate_static_tables(suits, variants):
 
 
 def _populate_suits(suits, suits_to_reverse):
+    logger.verbose("Populating suits and colors tables...")
+    logger.debug("Needing to reverse the following suits: {}".format(suits_to_reverse))
     for suit in suits:
         name: str = suit['name']
         display_name: str = suit.get('displayName', name)
@@ -65,6 +73,7 @@ def _populate_suits(suits, suits_to_reverse):
                 "(%s, %s, %s, %s, %s, %s, %s, %s)",
                 (suit_name, display_name, abbreviation, rank_clues, color_clues, dark, rev, prism)
             )
+            logger.debug("New suit {} imported.".format(name))
             cur.execute(
                 "SELECT id FROM suits WHERE name = %s",
                 (suit_name,)
@@ -78,6 +87,7 @@ def _populate_suits(suits, suits_to_reverse):
                         "ON CONFLICT (name) DO NOTHING",
                         (color,)
                     )
+                    logger.debug("New clue color {} imported.".format(color))
                 cur.execute(
                     "SELECT id FROM colors WHERE name = %s",
                     (color,)
@@ -92,6 +102,7 @@ def _populate_suits(suits, suits_to_reverse):
 
 
 def _populate_variants(variants):
+    logger.verbose("Populating variants table...")
     for var in variants:
         var_id = var['id']
         name = var['name']
@@ -145,7 +156,11 @@ def _populate_variants(variants):
             )
             suit_id = cur.fetchone()
             if suit_id is None:
-                print(suit)
+                err_msg = "Invalid suit name {} encountered while importing variant {} [{}]." \
+                          "Is the suits DB not populated?"\
+                    .format(suit, var_id, name)
+                logger.error(err_msg)
+                raise RuntimeError(err_msg)
 
             cur.execute(
                 "INSERT INTO variant_suits (variant_id, suit_id, index) VALUES (%s, %s, %s)",
@@ -154,6 +169,7 @@ def _populate_variants(variants):
 
 
 def _download_json_files():
+    logger.verbose("Downloading JSON files for suits and variants from github...")
     base_url = "https://raw.githubusercontent.com/Hanabi-Live/hanabi-live/main/packages/data/src/json"
     data = {}
     for name in ["suits", "variants"]:
@@ -161,8 +177,8 @@ def _download_json_files():
         url = base_url + "/" + filename
         response = requests.get(url)
         if not response.status_code == 200:
-            raise RuntimeError(
+            err_msg = "Could not download initialization file {} from github (tried url {})".format(filename, url)
-                "Could not download initialization file {} from github (tried url {})".format(filename, url)
+            logger.error(err_msg)
-            )
+            raise RuntimeError(err_msg)
         data[name] = json.loads(response.text)
     return data['suits'], data['variants']

download_data.py

@@ -26,6 +26,7 @@ def detailed_export_game(game_id: int, score: Optional[int] = None, var_id: Opti
     :param seed_exists: If specified and true, assumes that the seed is already present in database.
         If this is not the case, call will raise a DB insertion error
     """
+    logger.debug("Importing game {}".format(game_id))
 
     assert_msg = "Invalid response format from hanab.live while exporting game id {}".format(game_id)
 
@@ -60,12 +61,12 @@ def detailed_export_game(game_id: int, score: Optional[int] = None, var_id: Opti
     try:
         compressed_deck = compress_deck(deck)
     except InvalidFormatError:
-        print("Failed to compress deck while exporting game {}: {}".format(game_id, deck))
+        logger.error("Failed to compress deck while exporting game {}: {}".format(game_id, deck))
         raise
     try:
         compressed_actions = compress_actions(actions)
     except InvalidFormatError:
-        print("Failed to compress actions while exporting game {}".format(game_id))
+        logger.error("Failed to compress actions while exporting game {}".format(game_id))
         raise
 
     if not seed_exists:
@@ -75,6 +76,7 @@ def detailed_export_game(game_id: int, score: Optional[int] = None, var_id: Opti
             "ON CONFLICT (seed) DO NOTHING",
             (seed, num_players, var_id, compressed_deck)
         )
+        logger.debug("New seed {} imported.".format(seed))
 
     cur.execute(
         "INSERT INTO games ("
@@ -93,6 +95,7 @@ def detailed_export_game(game_id: int, score: Optional[int] = None, var_id: Opti
             all_or_nothing, compressed_actions
         )
     )
+    logger.debug("Imported game {}".format(game_id))
 
 
 def process_game_row(game: Dict, var_id):
@@ -117,6 +120,7 @@ def process_game_row(game: Dict, var_id):
         cur.execute("ROLLBACK TO seed_insert")
         detailed_export_game(game_id, score, var_id)
     cur.execute("RELEASE seed_insert")
+    logger.debug("Imported game {}".format(game_id))
 
 
 def download_games(var_id):
@@ -145,10 +149,9 @@ def download_games(var_id):
     last_page = (num_entries - 1) // page_size
 
     if num_already_downloaded_games == num_entries:
-        print("Already downloaded all games for variant {} [{}]".format(var_id, name))
+        logger.info("Already downloaded all games ({} many) for variant {} [{}]".format(num_entries, var_id, name))
         return
-
+    logger.info(
-    print(
         "Downloading remaining {} (total {}) entries for variant {} [{}]".format(
             num_entries - num_already_downloaded_games, num_entries, var_id, name
         )

log_setup/logger_setup.py

@@ -1,8 +1,8 @@
-import logging
+import logging, verboselogs
 
 
 def make_logger():
-    logger = logging.getLogger("hanab-suite")
+    logger = verboselogs.VerboseLogger("hanab-suite")
 
     logger.setLevel(logging.DEBUG)
 

requirements.txt

@@ -6,3 +6,4 @@ more_itertools
 psycopg2
 alive_progress
 argparse
+verboselogs

site_api.py

@@ -11,7 +11,7 @@ session = requests_cache.CachedSession('hanab.live')
 def get(url, refresh=False):
     #    print("sending request for " + url)
     query = "https://hanab.live/" + url
-    logger.debug("GET {}".format(query))
+    logger.debug("GET {} (force_refresh={})".format(query, refresh))
     response = session.get(query, force_refresh=refresh)
     if not response:
         logger.error("Failed to get request {} from hanab.live".format(query))

test.py

@@ -53,7 +53,8 @@ def export_all_seeds():
 
 if __name__ == "__main__":
     var_id = 964532
-#    export_all_seeds()
+    export_all_seeds()
+    exit(0)
 
 #    init_database_tables()
 #    populate_static_tables()