Merge pull request #508 from PR0M3TH3AN/codex/add-timing-logs-and-tests

Add verbose timing logs

src/nostr/client.py

@@ -101,6 +101,7 @@ class NostrClient:
         self.fingerprint = fingerprint
         self.fingerprint_dir = self.encryption_manager.fingerprint_dir
         self.config_manager = config_manager
+        self.verbose_timing = False
 
         if parent_seed is None:
             parent_seed = self.encryption_manager.decrypt_parent_seed()
@@ -123,6 +124,12 @@ class NostrClient:
         else:
             self.relays = relays
 
+        if self.config_manager is not None:
+            try:
+                self.verbose_timing = self.config_manager.get_verbose_timing()
+            except Exception:
+                self.verbose_timing = False
+
         # store the last error encountered during network operations
         self.last_error: Optional[str] = None
 
@@ -351,6 +358,7 @@ class NostrClient:
             Maximum chunk size in bytes. Defaults to 50 kB.
         """
 
+        start = time.perf_counter()
         if self.offline_mode or not self.relays:
             return Manifest(ver=1, algo="gzip", chunks=[]), ""
         await self._connect_async()
@@ -381,6 +389,9 @@ class NostrClient:
         manifest_id = result.id.to_hex() if hasattr(result, "id") else str(result)
         self.current_manifest = manifest
         self._delta_events = []
+        if getattr(self, "verbose_timing", False):
+            duration = time.perf_counter() - start
+            logger.info("publish_snapshot completed in %.2f seconds", duration)
         return manifest, manifest_id
 
     async def fetch_latest_snapshot(self) -> Tuple[Manifest, list[bytes]] | None:

src/password_manager/config_manager.py

@@ -58,6 +58,7 @@ class ConfigManager:
                 "min_lowercase": 2,
                 "min_digits": 2,
                 "min_special": 2,
+                "verbose_timing": False,
             }
         try:
             data = self.vault.load_config()
@@ -82,6 +83,7 @@ class ConfigManager:
             data.setdefault("min_lowercase", 2)
             data.setdefault("min_digits", 2)
             data.setdefault("min_special", 2)
+            data.setdefault("verbose_timing", False)
 
             # Migrate legacy hashed_password.enc if present and password_hash is missing
             legacy_file = self.fingerprint_dir / "hashed_password.enc"
@@ -315,3 +317,12 @@ class ConfigManager:
         """Retrieve the delay in seconds between Nostr retries."""
         cfg = self.load_config(require_pin=False)
         return float(cfg.get("nostr_retry_delay", 1.0))
+
+    def set_verbose_timing(self, enabled: bool) -> None:
+        cfg = self.load_config(require_pin=False)
+        cfg["verbose_timing"] = bool(enabled)
+        self.save_config(cfg)
+
+    def get_verbose_timing(self) -> bool:
+        cfg = self.load_config(require_pin=False)
+        return bool(cfg.get("verbose_timing", False))

src/password_manager/manager.py

@@ -138,6 +138,7 @@ class PasswordManager:
         self.offline_mode: bool = False
         self.profile_stack: list[tuple[str, Path, str]] = []
         self.last_unlock_duration: float | None = None
+        self.verbose_timing: bool = False
 
         # Initialize the fingerprint manager first
         self.initialize_fingerprint_manager()
@@ -247,6 +248,8 @@ class PasswordManager:
                 "yellow",
             )
         )
+        if getattr(self, "verbose_timing", False):
+            logger.info("Vault unlocked in %.2f seconds", self.last_unlock_duration)
 
     def initialize_fingerprint_manager(self):
         """
@@ -1014,6 +1017,7 @@ class PasswordManager:
             )
             self.secret_mode_enabled = bool(config.get("secret_mode_enabled", False))
             self.clipboard_clear_delay = int(config.get("clipboard_clear_delay", 45))
+            self.verbose_timing = bool(config.get("verbose_timing", False))
             if not self.offline_mode:
                 print("Connecting to relays...")
             self.nostr_client = NostrClient(
@@ -1034,6 +1038,7 @@ class PasswordManager:
 
     def sync_index_from_nostr(self) -> None:
         """Always fetch the latest vault data from Nostr and update the local index."""
+        start = time.perf_counter()
         try:
             result = asyncio.run(self.nostr_client.fetch_latest_snapshot())
             if not result:
@@ -1054,6 +1059,10 @@ class PasswordManager:
                 logger.info("Local database synchronized from Nostr.")
         except Exception as e:
             logger.warning(f"Unable to sync index from Nostr: {e}")
+        finally:
+            if getattr(self, "verbose_timing", False):
+                duration = time.perf_counter() - start
+                logger.info("sync_index_from_nostr completed in %.2f seconds", duration)
 
     def start_background_sync(self) -> None:
         """Launch a thread to synchronize the vault without blocking the UI."""

src/seedpass/cli.py

@@ -473,6 +473,9 @@ def config_set(ctx: typer.Context, key: str, value: str) -> None:
         "quick_unlock": lambda v: cfg.set_quick_unlock(
             v.lower() in ("1", "true", "yes", "y", "on")
         ),
+        "verbose_timing": lambda v: cfg.set_verbose_timing(
+            v.lower() in ("1", "true", "yes", "y", "on")
+        ),
     }
 
     action = mapping.get(key)

src/tests/test_verbose_timing.py

@@ -0,0 +1,32 @@
+import asyncio
+import logging
+
+from password_manager.manager import PasswordManager
+from helpers import dummy_nostr_client
+
+
+def test_unlock_vault_logs_time(monkeypatch, caplog, tmp_path):
+    pm = PasswordManager.__new__(PasswordManager)
+    pm.fingerprint_dir = tmp_path
+    pm.setup_encryption_manager = lambda path: None
+    pm.initialize_bip85 = lambda: None
+    pm.initialize_managers = lambda: None
+    pm.update_activity = lambda: None
+    pm.verbose_timing = True
+    caplog.set_level(logging.INFO, logger="password_manager.manager")
+    times = iter([0.0, 1.0])
+    monkeypatch.setattr(
+        "password_manager.manager.time.perf_counter", lambda: next(times)
+    )
+    pm.unlock_vault()
+    assert "Vault unlocked in 1.00 seconds" in caplog.text
+
+
+def test_publish_snapshot_logs_time(dummy_nostr_client, monkeypatch, caplog):
+    client, _relay = dummy_nostr_client
+    client.verbose_timing = True
+    caplog.set_level(logging.INFO, logger="nostr.client")
+    times = iter([0.0, 1.0])
+    monkeypatch.setattr("nostr.client.time.perf_counter", lambda: next(times))
+    asyncio.run(client.publish_snapshot(b"data"))
+    assert "publish_snapshot completed in 1.00 seconds" in caplog.text