Add more logging

Add more log statements including multiple DEBUG level log messages.

This should hopefully help with user issues where a single faulty entry
(eg. app manifest) causes a crash. Prior to this, the user was usually
instructed to launch Protontricks in a debugger to determine the exact
entry that causes Protontricks to crash; this is unnecessarily difficult
and time consuming for both the user and the person responding to the
report.

The issue template won't be updated to include the `-vv` flag yet. We
want to release a newer Protontricks version first.

src/protontricks/cli/main.py

@@ -386,6 +386,8 @@ def exit_(error):
             shell=True
         )
 
+    logger.info("Command returned %d", returncode)
+
     sys.exit(returncode)
 
 

src/protontricks/config.py

@@ -1,9 +1,10 @@
 import configparser
-
+import logging
 import os
-
 from pathlib import Path
 
+logger = logging.getLogger("protontricks")
+
 
 class Config:
     def __init__(self):
@@ -30,6 +31,10 @@ def set(self, section, option, value):
         Set the configuration value in the given section and its field, and
         save the configuration file
         """
+        logger.debug(
+            "Setting configuration field [%s][%s] = %s",
+            section, option, value
+        )
         self._parser.setdefault(section, {})
         self._parser[section][option] = value
 

src/protontricks/flatpak.py

@@ -64,6 +64,7 @@ def _get_xdg_user_dir(permission):
         )
         path = path.strip()
         path = os.fsdecode(path)
+        logger.debug("XDG path for %s is %s", permission, path)
         return Path(path)
 
     return None

src/protontricks/gui.py

@@ -413,11 +413,17 @@ def _map_path(path):
     inaccessible_paths = get_inaccessible_paths(paths)
     inaccessible_paths = set(map(str, inaccessible_paths))
 
+    logger.debug(
+        "Following inaccessible paths were found: %s", inaccessible_paths
+    )
+
     # Check what paths the user has ignored previously
     ignored_paths = set(
         json.loads(config.get("Dialog", "DismissedPaths", "[]"))
     )
 
+    logger.debug("Following paths have been ignored: %s", ignored_paths)
+
     # Remaining paths that are inaccessible and that haven't been dismissed
     # by the user
     remaining_paths = inaccessible_paths - ignored_paths

src/protontricks/steam.py

@@ -195,6 +195,10 @@ def from_appmanifest(cls, path, steam_lib_paths, steam_path=None):
 
         If 'steam_path' is provided, icon path is also populated
         """
+        logger.debug(
+            "Creating SteamApp from manifest file in %s", path
+        )
+
         try:
             content = path.read_text(encoding="utf-8")
         except UnicodeDecodeError:
@@ -533,6 +537,8 @@ def _iter_v28_appinfo(data, start):
             if i == len(data) - 4:
                 return
 
+    logger.debug("Loading appinfo.vdf in %s", path)
+
     # appinfo.vdf is not actually a (binary) VDF file, but a binary file
     # containing multiple binary VDF sections.
     # File structure based on comment from vdf developer:
@@ -548,6 +554,8 @@ def _iter_v28_appinfo(data, start):
 
     i += header_size
 
+    logger.debug("appinfo.vdf has magic number %s", magic)
+
     if magic == b"'DV\x07":
         # TODO: Remove this once V28 is used in stable version of Steam
         yield from _iter_v27_appinfo(data, i)
@@ -582,6 +590,8 @@ def get_tool_appid(compat_tool_name, steam_play_manifest):
         if "aliases" in entry:
             aliases += entry["aliases"].split(",")
 
+        logger.debug("%s has compat tool aliases %s", default_name, aliases)
+
         if compat_tool_name in aliases:
             return entry["appid"]
 
@@ -613,6 +623,8 @@ def _get_tool_app(compat_tool_name, steam_apps, steam_play_manifest):
         except StopIteration:
             return None
 
+    logger.debug("Finding Steam compat tool name for appid %s", appid)
+
     # Determine which Proton version to use (either globally or for
     # a specific app if `appid` was provided) by checking
     # `<steam_dir>/config/config.vdf` and `<steam_dir>/appcache/appinfo.vdf`.
@@ -648,6 +660,7 @@ def _get_tool_app(compat_tool_name, steam_apps, steam_play_manifest):
             vdf_data["installconfigstore"]["software"]["valve"]["steam"]
                     ["toolmapping"]
         )
+        logger.debug("Found ToolMapping entry")
     except KeyError:
         tool_mapping = {}
 
@@ -658,6 +671,7 @@ def _get_tool_app(compat_tool_name, steam_apps, steam_play_manifest):
             vdf_data["installconfigstore"]["software"]["valve"]["steam"]
                     ["compattoolmapping"]
         )
+        logger.debug("Found CompatToolMapping entry")
     except KeyError:
         compat_tool_mapping = {}
 
@@ -796,6 +810,10 @@ def get_prefix_modify_time(prefix_path):
             if prefix_path.is_dir():
                 candidates.append(prefix_path)
 
+    logger.debug(
+        "Found compatdata directories for app %s: %s", appid, candidates
+    )
+
     if len(candidates) > 1:
         # If we have more than one possible prefix path, use the one
         # with the most recent modification date
@@ -900,6 +918,12 @@ def parse_library_folders(data):
             if is_library_folder_xdg_steam and is_flatpak_steam:
                 path = flatpak_steam_path
 
+            logger.debug(
+                "Found Steam library folder %s. Is Flatpak path: %s, "
+                "Is XDG Steam path: %s.",
+                path, is_flatpak_steam, is_library_folder_xdg_steam
+            )
+
             library_folders.append(path)
 
         logger.info(
@@ -951,6 +975,10 @@ def get_compat_tool_dirs(steam_root):
     ]
     extra_ct_paths_env = os.getenv("STEAM_EXTRA_COMPAT_TOOLS_PATHS")
     if extra_ct_paths_env:
+        logger.debug(
+            "Including extra compat tool paths provided via env var: %s",
+            extra_ct_paths_env
+        )
         paths += [Path(path) for path in extra_ct_paths_env.split(os.pathsep)]
     paths += [steam_root / "compatibilitytools.d"]
 
@@ -1026,6 +1054,11 @@ def get_custom_compat_tool_installations_in_dir(compat_tool_dir):
             )
             continue
 
+        logger.debug(
+            "Found custom compatibility tool %s at %s",
+            internal_name, install_path
+        )
+
         custom_tool_apps.append(
             SteamApp(
                 name=internal_name, install_path=install_path,
@@ -1086,6 +1119,8 @@ def to_steamid3(steamid64):
         for user_id, user_data in user_datas
     ]
 
+    logger.debug("Found Steam user entries: %s", users)
+
     # Return the user with the highest timestamp, as that's likely to be the
     # currently logged-in user
     if users:
@@ -1197,6 +1232,10 @@ def get_custom_windows_shortcuts(steam_path, steam_lib_paths):
         if shortcut_data.get("icon", None):
             icon_path = Path(shortcut_data["icon"])
 
+        logger.debug(
+            "Creating SteamApp from non-Steam shortcut in %s", install_path
+        )
+
         steam_apps.append(
             SteamApp(
                 appid=appid,

tests/test_steam.py

@@ -369,8 +369,10 @@ def test_find_steam_default_proton(
 
         assert proton_app.name == "Proton 4.20"
 
-        record = caplog.records[-2]
-        assert "Using stable version of Proton" in record.message
+        assert any(
+            record for record in caplog.records
+            if "Using stable version of Proton" in record.message
+        )
 
 
 class TestFindLibraryPaths: