From 792accd177b2585091920490c5d63b089ffd2e88 Mon Sep 17 00:00:00 2001 From: David Fischer Date: Sat, 12 Sep 2026 16:09:18 -0700 Subject: [PATCH] Show progress during scrape We have the number of events almost immediately and we can show how many are left to do. In addition, this cleaned up some of the `--delay` code which was in more places than necessary --- pyproject.toml | 1 + src/cli.py | 38 ++++++++--- src/client.py | 7 -- src/models.py | 11 ++++ src/scraper.py | 110 +++++++++++++++++++------------ tests/test_cli.py | 53 +++++++++++++++ tests/test_client.py | 13 ---- tests/test_incremental.py | 132 +++++++++++++++++++++++++++++++++++++- tests/test_models.py | 16 +++++ uv.lock | 14 ++++ 10 files changed, 321 insertions(+), 74 deletions(-) create mode 100644 tests/test_cli.py diff --git a/pyproject.toml b/pyproject.toml index 2b5ff67..2cda900 100644 --- a/pyproject.toml +++ b/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] diff --git a/src/cli.py b/src/cli.py index 806ee55..bac175c 100644 --- a/src/cli.py +++ b/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, diff --git a/src/client.py b/src/client.py index bd1fdbc..e9db0c4 100644 --- a/src/client.py +++ b/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}" diff --git a/src/models.py b/src/models.py index 9b0f442..5d5d155 100644 --- a/src/models.py +++ b/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 ( diff --git a/src/scraper.py b/src/scraper.py index 7edcd18..d0151b4 100644 --- a/src/scraper.py +++ b/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 diff --git a/tests/test_cli.py b/tests/test_cli.py new file mode 100644 index 0000000..2fec732 --- /dev/null +++ b/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 diff --git a/tests/test_client.py b/tests/test_client.py index 21e405d..972c86d 100644 --- a/tests/test_client.py +++ b/tests/test_client.py @@ -159,19 +159,6 @@ def test_parse_event_no_decks_sets_last_error(): assert client.last_error == "Tournament has no decks (event likely did not fire)" -def test_fetch_event_data_with_request_delay(monkeypatch): - client = MTGOClient(request_delay=0.1) - mock_resp = MagicMock() - mock_resp.status_code = 404 - client.session.get = MagicMock(return_value=mock_resp) - - sleep_calls = [] - monkeypatch.setattr("time.sleep", lambda s: sleep_calls.append(s)) - - client.fetch_event_data("https://www.mtgo.com/decklist/test") - assert sleep_calls == [0.1] - - def test_fetch_calendar_skips_limited_events(): client = MTGOClient() mock_resp = MagicMock() diff --git a/tests/test_incremental.py b/tests/test_incremental.py index 9b73c67..4dbe70d 100644 --- a/tests/test_incremental.py +++ b/tests/test_incremental.py @@ -1,6 +1,7 @@ import json from datetime import date from unittest.mock import MagicMock +from unittest.mock import patch from src.models import Tournament from src.scraper import MTGOSyncEngine @@ -76,7 +77,10 @@ def test_deferred_retry_succeeds(tmp_path): ) stats = engine.sync( - start_date=date(2026, 9, 1), end_date=date(2026, 9, 1), retry_delay=0 + start_date=date(2026, 9, 1), + end_date=date(2026, 9, 1), + retry_delay=0, + delay=0, ) assert stats["created"] == 1 @@ -105,7 +109,10 @@ def test_deferred_retry_fails_both(tmp_path): ) stats = engine.sync( - start_date=date(2026, 9, 1), end_date=date(2026, 9, 1), retry_delay=0 + start_date=date(2026, 9, 1), + end_date=date(2026, 9, 1), + retry_delay=0, + delay=0, ) assert stats["created"] == 0 @@ -164,7 +171,7 @@ def test_sync_specified_tournaments(tmp_path): normalizer=mock_normalizer, ) - stats = engine.sync(tournaments=[mock_tournament], retry_delay=0) + stats = engine.sync(tournaments=[mock_tournament], retry_delay=0, delay=0) assert stats["total_found"] == 1 assert stats["created"] == 1 @@ -173,6 +180,37 @@ def test_sync_specified_tournaments(tmp_path): assert mock_client.fetch_calendar.call_count == 0 +def test_sync_tqdm_progress_updates(tmp_path): + mock_client = MagicMock() + mock_tournament = Tournament( + date=date(2026, 9, 1), + name="Targeted Challenge", + uri="https://www.mtgo.com/decklist/targeted-challenge-2026-09-01123", + formats="Modern", + json_file="targeted-challenge-2026-09-01123.json", + ) + mock_client.fetch_event_data.return_value = {"decklists": [{"player": "P1"}]} + mock_item = MagicMock() + mock_item.to_dict.return_value = {"Tournament": {"Name": "Targeted Challenge"}} + mock_client.parse_event.return_value = mock_item + + engine = MTGOSyncEngine( + cache_root=str(tmp_path), + client=mock_client, + normalizer=MagicMock(), + ) + + with patch("src.scraper.tqdm") as mock_tqdm: + mock_pbar = MagicMock() + mock_pbar.__iter__.return_value = [mock_tournament] + mock_tqdm.return_value = mock_pbar + + engine.sync(tournaments=[mock_tournament], retry_delay=0, delay=0) + + mock_tqdm.assert_called_once() + mock_pbar.set_postfix_str.assert_called_with("targeted-challenge-2026-09-01123") + + def test_sync_skips_limited_event(tmp_path): mock_client = MagicMock() limited_tournament = Tournament( @@ -224,3 +262,91 @@ def test_cli_parse_retry_args(monkeypatch): monkeypatch.setattr("sys.argv", ["main.py"]) args_default = parse_args() assert args_default.delay == 0.1 + + +def test_sync_delay_applied_on_fetch_only(tmp_path, monkeypatch): + mock_client = MagicMock() + limited_t = Tournament( + date=date(2026, 9, 1), + name="Limited Prelim", + uri="https://www.mtgo.com/limited", + json_file="limited.json", + ) + normal_t = Tournament( + date=date(2026, 9, 1), + name="Modern Prelim", + uri="https://www.mtgo.com/modern", + json_file="modern.json", + ) + mock_client.fetch_event_data.return_value = {"decklists": [{"player": "P1"}]} + mock_item = MagicMock() + mock_item.to_dict.return_value = {"Tournament": {"Name": "Modern Prelim"}} + mock_client.parse_event.return_value = mock_item + + sleep_calls = [] + monkeypatch.setattr("time.sleep", lambda s: sleep_calls.append(s)) + + engine = MTGOSyncEngine( + cache_root=str(tmp_path), + client=mock_client, + delay=0.5, + ) + stats = engine.sync(tournaments=[limited_t, normal_t], retry_delay=0) + + assert stats["skipped"] == 1 + assert stats["created"] == 1 + assert sleep_calls == [0.5] + + +def test_sync_tournament_return_statuses(tmp_path): + mock_client = MagicMock() + mock_normalizer = MagicMock() + engine = MTGOSyncEngine( + cache_root=str(tmp_path), client=mock_client, normalizer=mock_normalizer + ) + + # 1. Limited event -> skipped + limited_t = Tournament( + date=date(2026, 9, 1), + name="Limited Prelim", + json_file="limited.json", + ) + res = engine._sync_tournament( + limited_t, force=False, lookback_days=2, today=date(2026, 9, 2) + ) + assert res == "skipped" + + # 2. Fetch failure -> failed + mock_client.fetch_event_data.return_value = None + fail_t = Tournament( + date=date(2026, 9, 1), + name="Pauper Prelim", + uri="https://www.mtgo.com/pauper", + json_file="pauper.json", + ) + res = engine._sync_tournament( + fail_t, force=False, lookback_days=2, today=date(2026, 9, 2) + ) + assert res == "failed" + + # 3. Valid event -> created + mock_client.fetch_event_data.return_value = { + "decklists": [{"player": "P1"}], + "player_count": {"players": "8"}, + } + mock_item = MagicMock() + mock_item.to_dict.return_value = { + "Tournament": {"Name": "Pauper Prelim", "PlayerCount": 8}, + "Decks": [{"player": "P1"}], + } + mock_client.parse_event.return_value = mock_item + res = engine._sync_tournament( + fail_t, force=False, lookback_days=2, today=date(2026, 9, 2) + ) + assert res == "created" + + # 4. Same event when file already exists and unchanged -> skipped + res = engine._sync_tournament( + fail_t, force=False, lookback_days=2, today=date(2026, 9, 2) + ) + assert res == "skipped" diff --git a/tests/test_models.py b/tests/test_models.py index b4e38a6..1f9bb5a 100644 --- a/tests/test_models.py +++ b/tests/test_models.py @@ -100,3 +100,19 @@ def test_tournament_failed_dict_roundtrip(): repr(reconstituted) == "Tournament(Modern Challenge 64, 2026-09-10, players=None, reason='HTTP 404')" ) + + +def test_tournament_event_id(): + t1 = Tournament(json_file="standard-league-2024-07-258335.json") + assert t1.event_id == "standard-league-2024-07-258335" + + t2 = Tournament( + uri="https://www.mtgo.com/decklist/modern-challenge-64-2026-09-1012854060" + ) + assert t2.event_id == "modern-challenge-64-2026-09-1012854060" + + t3 = Tournament(name="Pauper League") + assert t3.event_id == "Pauper League" + + t4 = Tournament() + assert t4.event_id == "unknown" diff --git a/uv.lock b/uv.lock index 6f6bd28..e9515ad 100644 --- a/uv.lock +++ b/uv.lock @@ -189,6 +189,7 @@ dependencies = [ { name = "beautifulsoup4" }, { name = "python-dateutil" }, { name = "requests" }, + { name = "tqdm" }, ] [package.dev-dependencies] @@ -203,6 +204,7 @@ requires-dist = [ { name = "beautifulsoup4", specifier = ">=4.12.0" }, { name = "python-dateutil", specifier = ">=2.9.0" }, { name = "requests", specifier = ">=2.31.0" }, + { name = "tqdm", specifier = ">=4.70.1" }, ] [package.metadata.requires-dev] @@ -397,6 +399,18 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/eb/dc/ad025c1ee131eba60c69f4dd5779b18fcf1e6b21a343e2162a84d5d133c7/soupsieve-2.9.2-py3-none-any.whl", hash = "sha256:8089a26fd974ca7a1f30276d3d8492ab266ab15af581642dfe8aa162e0c1c823", size = 37370, upload-time = "2026-08-07T00:57:23.524Z" }, ] +[[package]] +name = "tqdm" +version = "4.70.1" +source = { registry = "https://pypi.org/simple" } +dependencies = [ + { name = "colorama", marker = "sys_platform == 'win32'" }, +] +sdist = { url = "https://files.pythonhosted.org/packages/0d/ea/b2a5bd54b28a324dae8211928b2d730b6547500342c7e6c6dea08bd0a485/tqdm-4.70.1.tar.gz", hash = "sha256:cefd0eca11b2a37a3aee776544d4f4ae913f02688135b5556b8788dfa474afc4", size = 171846, upload-time = "2026-09-11T07:25:16.601Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/a7/03/921a3d3c75785aca9ebfbfcabfbc3a1be12e2ab5265deb026d55a5a3f83e/tqdm-4.70.1-py3-none-any.whl", hash = "sha256:c293e525e6fef9c20e8728fd4612df02a0aa31bb5fe91ecd93e123b1b7bffa73", size = 80199, upload-time = "2026-09-11T07:25:14.599Z" }, +] + [[package]] name = "typing-extensions" version = "4.16.0"