Show progress during scrape

pyproject.toml

@@ -15,6 +15,7 @@ dependencies = [
     "beautifulsoup4>=4.12.0",
     "python-dateutil>=2.9.0",
     "requests>=2.31.0",
+    "tqdm>=4.70.1",
 ]
 
 [project.scripts]

src/cli.py

@@ -18,22 +18,42 @@
 from .scraper import save_failed_events
 
 
+class LevelFilter(logging.Filter):
+    """Filter to allow only records at or above a minimum log level."""
+
+    def __init__(self, min_level: int):
+        super().__init__()
+        self.min_level = min_level
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        return record.levelno >= self.min_level
+
+
 def setup_logging(verbose: bool = False, log_file: Optional[str] = None):
     if not log_file:
         log_file = datetime.now().strftime("scraper_%Y%m%d-%H%M%S.log")
 
-    level = logging.DEBUG if verbose else logging.INFO
+    file_level = logging.DEBUG if verbose else logging.INFO
+    console_level = logging.DEBUG if verbose else logging.WARNING
+
     log_format = "[%(asctime)s] [%(levelname)s] %(name)s: %(message)s"
     date_format = "%Y-%m-%d %H:%M:%S"
+    formatter = logging.Formatter(log_format, date_format)
 
-    handlers = [
-        logging.StreamHandler(sys.stdout),
-        logging.FileHandler(log_file, encoding="utf-8"),
-    ]
+    console_handler = logging.StreamHandler(sys.stdout)
+    console_handler.setLevel(console_level)
+    console_handler.addFilter(LevelFilter(console_level))
+    console_handler.setFormatter(formatter)
 
-    logging.basicConfig(
-        level=level, format=log_format, datefmt=date_format, handlers=handlers
-    )
+    file_handler = logging.FileHandler(log_file, encoding="utf-8")
+    file_handler.setLevel(file_level)
+    file_handler.setFormatter(formatter)
+
+    root_logger = logging.getLogger()
+    root_logger.setLevel(min(file_level, console_level))
+    root_logger.handlers.clear()
+    root_logger.addHandler(console_handler)
+    root_logger.addHandler(file_handler)
 
 
 def parse_args():
@@ -147,7 +167,7 @@ def main():
             f"Loaded {len(tournaments_to_sync)} tournament(s) to retry from '{args.retry_failed}'."
         )
 
-    engine = MTGOSyncEngine(cache_root=args.cache_dir, request_delay=args.delay)
+    engine = MTGOSyncEngine(cache_root=args.cache_dir, delay=args.delay)
     stats = engine.sync(
         start_date=start_date,
         end_date=end_date,

src/client.py

@@ -18,7 +18,6 @@
 from requests.adapters import HTTPAdapter
 from urllib3.util.retry import Retry
 
-from .config import DEFAULT_REQUEST_DELAY
 from .config import MTGO_LIST_URL
 from .config import MTGO_ROOT_URL
 from .config import VALID_FORMATS
@@ -99,12 +98,10 @@ def __init__(
         self,
         session: Optional[requests.Session] = None,
         max_retries: int = 2,
-        request_delay: float = DEFAULT_REQUEST_DELAY,
     ):
         self.session = session or requests.Session()
         self.session.headers.update({"User-Agent": get_user_agent()})
         self.max_retries = max_retries
-        self.request_delay = request_delay
         self.last_error: Optional[str] = None
 
         retry_strategy = Retry(
@@ -137,8 +134,6 @@ def fetch_calendar(self, start_date: date, end_date: date) -> List[Tournament]:
             logger.info("Fetching calendar: %s", url)
 
             try:
-                if self.request_delay > 0:
-                    time.sleep(self.request_delay)
                 resp = self.session.get(url, timeout=30)
                 if resp.status_code != 200:
                     logger.warning(
@@ -212,8 +207,6 @@ def fetch_event_data(self, event_url: str) -> Optional[dict]:
         self.last_error = None
         for attempt in range(1, self.max_retries + 1):
             try:
-                if self.request_delay > 0:
-                    time.sleep(self.request_delay)
                 resp = self.session.get(event_url, timeout=30)
                 if resp.status_code != 200:
                     self.last_error = f"HTTP {resp.status_code}"

src/models.py

@@ -1,5 +1,6 @@
 """Data models matching MTG_decklistcache format with PlayerCount extension."""
 
+import os
 from datetime import date
 from datetime import datetime
 from typing import List
@@ -25,6 +26,16 @@ def __init__(
         self.player_count = player_count
         self.failure_reason = failure_reason
 
+    @property
+    def event_id(self) -> str:
+        """Return the event identifier slug, falling back to name or unknown."""
+        if self.json_file:
+            return os.path.splitext(self.json_file)[0]
+        if self.uri:
+            clean_url = self.uri.split("?")[0].rstrip("/")
+            return os.path.splitext(os.path.basename(clean_url))[0]
+        return self.name or "unknown"
+
     def __repr__(self):
         reason = f", reason='{self.failure_reason}'" if self.failure_reason else ""
         return (

src/scraper.py

@@ -11,9 +11,13 @@
 from datetime import timedelta
 from datetime import timezone
 from typing import List
+from typing import Literal
 from typing import Optional
 from typing import Tuple
 
+from tqdm import tqdm
+from tqdm.contrib.logging import logging_redirect_tqdm
+
 from .client import MTGOClient
 from .client import tournament_from_url
 from .config import DEFAULT_LOOKBACK_DAYS
@@ -70,13 +74,13 @@ def __init__(
         scryfall_cache_dir: str = ".cache",
         normalizer: Optional[ScryfallNormalizer] = None,
         client: Optional[MTGOClient] = None,
-        request_delay: float = DEFAULT_REQUEST_DELAY,
+        delay: float = DEFAULT_REQUEST_DELAY,
+        request_delay: Optional[float] = None,
     ):
         self.cache_root = os.path.abspath(cache_root)
         self.scryfall_cache_dir = scryfall_cache_dir
-        self.client = client or MTGOClient(request_delay=request_delay)
-        if client and hasattr(self.client, "request_delay"):
-            self.client.request_delay = request_delay
+        self.client = client or MTGOClient()
+        self.delay = request_delay if request_delay is not None else delay
 
         # Lazily loaded
         # This checks and updates the Scryfall cache if necessary
@@ -128,16 +132,14 @@ def _sync_tournament(
         force: bool,
         lookback_days: int,
         today: date,
-        stats: dict,
-    ) -> bool:
+    ) -> Literal["created", "updated", "skipped", "failed"]:
         # Fallback date if missing
         if not t.date:
             t.date = today
 
         if t.name and t.name.startswith("Limited"):
             logger.info("Skipping Limited event: %s", t.name)
-            stats["skipped"] += 1
-            return True
+            return "skipped"
 
         safe_filename = sanitize_filename(t.json_file or "unknown.json")
         target_dir = os.path.join(
@@ -172,8 +174,7 @@ def _sync_tournament(
                 else None
             )
             if cached_pc is not None:
-                stats["skipped"] += 1
-                return True
+                return "skipped"
 
         logger.info("Checking tournament: %s (%s)", t.name, t.uri)
         raw_event = self.client.fetch_event_data(t.uri)
@@ -185,7 +186,7 @@ def _sync_tournament(
             logger.warning(
                 "Failed to fetch event data for %s: %s", t.uri, t.failure_reason
             )
-            return False
+            return "failed"
 
         # Compare with cache if file exists
         if file_exists and not force and cached_data:
@@ -207,8 +208,7 @@ def _sync_tournament(
                     remote_decks,
                     remote_pc,
                 )
-                stats["skipped"] += 1
-                return True
+                return "skipped"
             else:
                 logger.info(
                     "Update detected for %s: decks (%d -> %d), player_count (%s -> %s)",
@@ -231,18 +231,16 @@ def _sync_tournament(
                 safe_filename,
                 t.failure_reason,
             )
-            return False
+            return "failed"
 
         atomic_write_json(target_path, item.to_dict())
         t.failure_reason = None
         if file_exists:
-            stats["updated"] += 1
             logger.info("Updated: %s", target_path)
+            return "updated"
         else:
-            stats["created"] += 1
             logger.info("Created: %s", target_path)
-
-        return True
+            return "created"
 
     def sync(
         self,
@@ -254,8 +252,11 @@ def sync(
         skip_leagues: bool = False,
         retry_delay: int = 5,
         tournaments: Optional[List[Tournament]] = None,
+        disable_progress: bool = False,
+        delay: Optional[float] = None,
     ) -> dict:
         """Run synchronization across the resolved date range (or given tournaments) with deferred retry."""
+        effective_delay = self.delay if delay is None else delay
         if tournaments is None:
             start, end = self.resolve_date_range(
                 start_date, end_date, auto_resume, lookback_days
@@ -279,34 +280,59 @@ def sync(
         today = datetime.now(timezone.utc).date()
         deferred_retries = []
 
-        for t in tournaments:
-            success = self._sync_tournament(t, force, lookback_days, today, stats)
-            if not success:
-                logger.warning(
-                    "Queueing %s (%s) for deferred retry at end of run",
-                    t.name,
-                    t.json_file,
-                )
-                deferred_retries.append(t)
-
-        if deferred_retries:
-            logger.info(
-                "Starting deferred retry pass for %d failed event(s)...",
-                len(deferred_retries),
+        with logging_redirect_tqdm():
+            pbar = tqdm(
+                tournaments,
+                desc="Syncing events",
+                unit="event",
+                disable=disable_progress,
             )
-            if retry_delay > 0:
-                time.sleep(retry_delay)
-            for t in deferred_retries:
-                logger.info("Deferred retry: %s (%s)", t.name, t.json_file)
-                success = self._sync_tournament(t, force, lookback_days, today, stats)
-                if not success:
-                    logger.error(
-                        "Deferred retry also failed for %s (%s). Marking as failed.",
+            for t in pbar:
+                pbar.set_postfix_str(t.event_id)
+                result = self._sync_tournament(t, force, lookback_days, today)
+                if result == "failed":
+                    logger.warning(
+                        "Queueing %s (%s) for deferred retry at end of run",
                         t.name,
                         t.json_file,
                     )
-                    stats["failed"] += 1
-                    stats["failed_events"].append(t)
+                    deferred_retries.append(t)
+                else:
+                    stats[result] += 1
+
+                if result != "skipped" and effective_delay > 0:
+                    time.sleep(effective_delay)
+
+            if deferred_retries:
+                logger.info(
+                    "Starting deferred retry pass for %d failed event(s)...",
+                    len(deferred_retries),
+                )
+                if retry_delay > 0:
+                    time.sleep(retry_delay)
+                retry_pbar = tqdm(
+                    deferred_retries,
+                    desc="Retrying failed events",
+                    unit="event",
+                    disable=disable_progress,
+                )
+                for t in retry_pbar:
+                    retry_pbar.set_postfix_str(t.event_id)
+                    logger.info("Deferred retry: %s (%s)", t.name, t.json_file)
+                    result = self._sync_tournament(t, force, lookback_days, today)
+                    if result == "failed":
+                        logger.error(
+                            "Deferred retry also failed for %s (%s). Marking as failed.",
+                            t.name,
+                            t.json_file,
+                        )
+                        stats["failed"] += 1
+                        stats["failed_events"].append(t)
+                    else:
+                        stats[result] += 1
+
+                    if result != "skipped" and effective_delay > 0:
+                        time.sleep(effective_delay)
 
         logger.info("Sync complete! Stats: %s", stats)
         return stats

tests/test_cli.py

@@ -0,0 +1,53 @@
+import io
+import logging
+import sys
+
+from src.cli import LevelFilter
+from src.cli import setup_logging
+
+
+def test_level_filter():
+    f = LevelFilter(logging.WARNING)
+    info_record = logging.LogRecord("test", logging.INFO, "path", 1, "msg", (), None)
+    warn_record = logging.LogRecord("test", logging.WARNING, "path", 1, "msg", (), None)
+    assert not f.filter(info_record)
+    assert f.filter(warn_record)
+
+
+def test_setup_logging_levels(tmp_path, monkeypatch):
+    log_file = tmp_path / "test.log"
+    fake_stdout = io.StringIO()
+    monkeypatch.setattr(sys, "stdout", fake_stdout)
+
+    setup_logging(verbose=False, log_file=str(log_file))
+
+    logger = logging.getLogger("test_logger")
+    logger.info("This is an info message")
+    logger.warning("This is a warning message")
+
+    stdout_output = fake_stdout.getvalue()
+    assert "This is an info message" not in stdout_output
+    assert "This is a warning message" in stdout_output
+
+    assert log_file.exists()
+    log_file_content = log_file.read_text(encoding="utf-8")
+    assert "This is an info message" in log_file_content
+    assert "This is a warning message" in log_file_content
+
+
+def test_setup_logging_verbose(tmp_path, monkeypatch):
+    log_file = tmp_path / "test_verbose.log"
+    fake_stdout = io.StringIO()
+    monkeypatch.setattr(sys, "stdout", fake_stdout)
+
+    setup_logging(verbose=True, log_file=str(log_file))
+
+    logger = logging.getLogger("test_logger_verbose")
+    logger.debug("This is a debug message")
+
+    stdout_output = fake_stdout.getvalue()
+    assert "This is a debug message" in stdout_output
+
+    assert log_file.exists()
+    log_file_content = log_file.read_text(encoding="utf-8")
+    assert "This is a debug message" in log_file_content