diff --git a/CHANGELOG.md b/CHANGELOG.md index a4911cd..c6f88d1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -38,6 +38,7 @@ bad default or violating the promise quietly. ### Changed +- A page that never loads is now logged with the browser's own reason, in all three engines. Before, Playwright logged every failed navigation as "Timeout loading ..." with no reason, even when the error came 64 ms after the navigation started (canary 2026-10-20, topic run through `QUORA_PROXY`). Now a real timeout still reads "Timeout loading", any other navigation error reads "Navigation failed loading", and both include the error's first line with proxy credentials masked. The sidecar gains `load_error`: the reason for the first page that never loaded, or `null`. Exit codes and `stop_reason` are unchanged. - CI only: the canary now runs weekly (Mondays 06:20 UTC) and on a manual dispatch, with its optional secret `QUORA_PROXY` passed on every run; the daily schedule is removed. ## [0.2.0] — 2026-10-16 diff --git a/playwright_scraper.py b/playwright_scraper.py index 7b5f9b3..20fa1cf 100644 --- a/playwright_scraper.py +++ b/playwright_scraper.py @@ -173,6 +173,10 @@ class PageOutcome: # a floor rather than the whole feed, and a run that reported it as # complete would read as a shrinking catalogue. scroll: Optional[dict] = None + # The browser's own words for the last failed navigation (first line, + # credentials masked), so a load that failed in 60 ms is not reported as + # a timeout with nothing to say why. + load_error: Optional[str] = None @property def ok(self) -> bool: @@ -531,6 +535,16 @@ def _mask_credentials(text: str) -> str: return _CREDENTIALS_IN_URL_RE.sub(r"\1***:***@", text or "") +def _load_error_text(exc) -> str: + """The first line of a navigation error, credentials masked. + + Playwright's message runs on into a multi-line call log; its first line + carries the reason (`net::ERR_...` or `Timeout 60000ms exceeded`). + """ + lines = str(exc).strip().splitlines() + return _mask_credentials(lines[0] if lines else type(exc).__name__)[:200] + + def _content_when_settled(page, attempts: int = 4, pause_ms: int = 700): """page.content() that tolerates a page mid-navigation. @@ -719,6 +733,7 @@ def _fetch_one_page(session, args, pool, page_num: int, url: Optional[str]) -> P # judges by the document alone. http_status = None html, state, load_failed = None, "ok", False + load_error = None for block_attempt in range(block_retries + 1): load_failed, exit_failed = False, None @@ -741,6 +756,7 @@ def _fetch_one_page(session, args, pool, page_num: int, url: Optional[str]) -> P # catching only the latter lets it escape as a traceback, # which is the likeliest failure the first time anyone # points --proxy-file at a real list. + load_error = _load_error_text(e) reason = _proxy_failure(e) if reason: exit_failed, load_failed = reason, True @@ -748,9 +764,16 @@ def _fetch_one_page(session, args, pool, page_num: int, url: Optional[str]) -> P load_failed = True if attempt < args.retries: pause = args.retry_delay * (2 ** (attempt - 1)) - logger.warning("Timeout loading %s (attempt %d/%d) — " - "retrying in %.1fs.", url, attempt, - args.retries, pause) + # Only a PWTimeout is a timeout. Any other PWError + # (an exit that drops the tunnel, a refused + # connection) fails in milliseconds and used to be + # logged as "Timeout" with no reason at all. + logger.warning("%s loading %s (attempt %d/%d: %s) — " + "retrying in %.1fs.", + "Timeout" if isinstance(e, PWTimeout) + else "Navigation failed", + url, attempt, args.retries, load_error, + pause) time.sleep(pause) else: logger.info("Extending the feed to batch %d/%d by scrolling " @@ -911,8 +934,10 @@ def _fetch_one_page(session, args, pool, page_num: int, url: Optional[str]) -> P break if load_failed: - logger.error("Gave up loading %s after %d attempt(s).", url, args.retries) + logger.error("Gave up loading %s after %d attempt(s): %s", url, + args.retries, load_error or "no error text") outcome.load_failed = True + outcome.load_error = load_error return outcome outcome.state = state @@ -1256,6 +1281,9 @@ def scrape(args) -> int: # pagination model before comparing anything: a "page" here is a # scroll batch, not an address. "pagination": "infinite-scroll", + # The browser's reason for the first page that never loaded, so a + # sidecar saying page_load_timeout also says what actually failed. + "load_error": next((o.load_error for o in outcomes if o.load_error), None), } return finish_run(all_rows, args.out, args.format, args.allow_empty, diff --git a/puppeteer_scraper.py b/puppeteer_scraper.py index 5a7480a..04e1a16 100644 --- a/puppeteer_scraper.py +++ b/puppeteer_scraper.py @@ -181,6 +181,9 @@ class PageOutcome: answers_available: Optional[int] = None gap: Optional[int] = None scroll: Optional[dict] = None + # The driver's own words for the last failed navigation (first line, + # credentials masked). See the Playwright engine. + load_error: Optional[str] = None @property def ok(self) -> bool: @@ -196,6 +199,12 @@ def _mask_credentials(text: str) -> str: return _CREDENTIALS_IN_URL_RE.sub(r"\1***:***@", text or "") +def _load_error_text(exc) -> str: + """The first line of a navigation error, credentials masked.""" + lines = str(exc).strip().splitlines() + return _mask_credentials(lines[0] if lines else type(exc).__name__)[:200] + + def _chrome_ua(version: str) -> str: """A desktop-Chrome UA from the browser's own reported version. @@ -481,6 +490,7 @@ def _fetch_one_page(session, args, pool, page_num: int, # judges by the document alone. http_status = None html, state, load_failed = None, "ok", False + load_error = None for block_attempt in range(block_retries + 1): load_failed = False @@ -498,11 +508,14 @@ def _fetch_one_page(session, args, pool, page_num: int, break except Exception as e: # noqa: BLE001 load_failed = True + load_error = _load_error_text(e) if attempt < args.retries: pause = args.retry_delay * (2 ** (attempt - 1)) - logger.warning("Timeout loading %s (attempt %d/%d: " - "%s) — retrying in %.1fs.", url, - attempt, args.retries, str(e)[:120], + logger.warning("%s loading %s (attempt %d/%d: " + "%s) — retrying in %.1fs.", + "Timeout" if type(e).__name__ == "TimeoutError" + else "Navigation failed", + url, attempt, args.retries, load_error, pause) time.sleep(pause) else: @@ -616,8 +629,10 @@ def _fetch_one_page(session, args, pool, page_num: int, break if load_failed: - logger.error("Gave up loading %s after %d attempt(s).", url, args.retries) + logger.error("Gave up loading %s after %d attempt(s): %s", url, + args.retries, load_error or "no error text") outcome.load_failed = True + outcome.load_error = load_error return outcome outcome.state = state @@ -869,6 +884,7 @@ def scrape(args) -> int: "inline_payload_rows": sum(1 for r in all_rows if r.data_source != "dom"), "pagination": "infinite-scroll", + "load_error": next((o.load_error for o in outcomes if o.load_error), None), } return finish_run(all_rows, args.out, args.format, args.allow_empty, diff --git a/selenium_scraper.py b/selenium_scraper.py index 0b4dfd7..0b6f839 100644 --- a/selenium_scraper.py +++ b/selenium_scraper.py @@ -88,6 +88,12 @@ def _mask_credentials(text: str) -> str: return _CREDENTIALS_IN_URL_RE.sub(r"\1***:***@", text or "") +def _load_error_text(exc) -> str: + """The first line of a navigation error, credentials masked.""" + lines = str(exc).strip().splitlines() + return _mask_credentials(lines[0] if lines else type(exc).__name__)[:200] + + def _chrome_ua(version: str) -> str: """A desktop-Chrome UA naming the browser's OWN real version.""" return (f"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 " @@ -134,6 +140,9 @@ class PageOutcome: answers_available: Optional[int] = None gap: Optional[int] = None scroll: Optional[dict] = None + # The driver's own words for the last failed navigation (first line, + # credentials masked). See the Playwright engine. + load_error: Optional[str] = None @property def ok(self) -> bool: @@ -507,6 +516,7 @@ def _fetch_one_page(session, args, pool, page_num: int, # judges by the document alone. http_status = None html, state, load_failed = None, "ok", False + load_error = None for block_attempt in range(block_retries + 1): load_failed = False @@ -520,12 +530,15 @@ def _fetch_one_page(session, args, pool, page_num: int, break except (TimeoutException, WebDriverException) as e: load_failed = True + load_error = _load_error_text(e) if attempt < args.retries: pause = args.retry_delay * (2 ** (attempt - 1)) - logger.warning("Timeout loading %s (attempt %d/%d: " - "%s) — retrying in %.1fs.", url, - attempt, args.retries, - str(e)[:120], pause) + logger.warning("%s loading %s (attempt %d/%d: " + "%s) — retrying in %.1fs.", + "Timeout" if isinstance(e, TimeoutException) + else "Navigation failed", + url, attempt, args.retries, load_error, + pause) time.sleep(pause) else: logger.info("Extending the feed to batch %d/%d by scrolling " @@ -638,8 +651,10 @@ def _fetch_one_page(session, args, pool, page_num: int, break if load_failed: - logger.error("Gave up loading %s after %d attempt(s).", url, args.retries) + logger.error("Gave up loading %s after %d attempt(s): %s", url, + args.retries, load_error or "no error text") outcome.load_failed = True + outcome.load_error = load_error return outcome outcome.state = state @@ -890,6 +905,7 @@ def scrape(args) -> int: "inline_payload_rows": sum(1 for r in all_rows if r.data_source != "dom"), "pagination": "infinite-scroll", + "load_error": next((o.load_error for o in outcomes if o.load_error), None), } return finish_run(all_rows, args.out, args.format, args.allow_empty, diff --git a/smoke_test.py b/smoke_test.py index eee0064..cfc8b7e 100644 --- a/smoke_test.py +++ b/smoke_test.py @@ -2264,17 +2264,17 @@ class _StubChallenge: kind, source, sitekey, action = "recaptcha-v2", "stub", "stub-key", None -def _stub_args(tmp): +def _stub_args(tmp, retries=1): import argparse return argparse.Namespace( - retries=1, pages=1, retry_delay=0.0, delay=0.0, proxy_block_retries=2, + retries=retries, pages=1, retry_delay=0.0, delay=0.0, proxy_block_retries=2, mode="topic", out=os.path.join(tmp, "out"), dump_html=None, headless=True, solve_captcha="when-blocked", twocaptcha_key="stub-not-a-key", captcha_api="v2", min_score=0.7) def _drive_engine(engine, state, detections=None, solver_raises=False, - rows=None, status=None): + rows=None, status=None, goto_raises=None, retries=1): """Run one `_fetch_one_page` with every driver primitive stubbed. Returns (outcome, solver purchases). Nothing reaches the network: the @@ -2299,6 +2299,12 @@ def solve(*a, **k): goto_response.status = status session.page.goto.return_value = goto_response session.bridge.run.return_value = goto_response + if goto_raises is not None: + # Every navigation fails with this error (pyppeteer's goto goes + # through bridge.run, Selenium's through driver.get). + session.page.goto.side_effect = goto_raises + session.bridge.run.side_effect = goto_raises + session.driver.get.side_effect = goto_raises patches = { "detect_recaptcha_v3": lambda *a, **k: None, "detect_recaptcha_in_page": lambda *a, **k: None, @@ -2318,7 +2324,7 @@ def solve(*a, **k): setattr(engine, n, v) with tempfile.TemporaryDirectory() as tmp: outcome = engine._fetch_one_page( - session, _stub_args(tmp), None, 1, + session, _stub_args(tmp, retries), None, 1, "https://www.quora.com/topic/Machine-Learning") finally: for n, v in saved.items(): @@ -2326,6 +2332,65 @@ def solve(*a, **k): return outcome, len(purchases) +def _navigation_errors(name): + """(instant failure, timeout) exceptions as `name`'s driver raises them. + + The texts follow Chromium's format. The first one carries a credential + in a URL, which must never reach a log or the sidecar.""" + instant = ("Page.goto: net::ERR_CONNECTION_CLOSED at " + "https://www.quora.com/topic/Machine-Learning via " + "http://" + "canary-login" + ":" + "not-a-real-pass" + + "@proxy.invalid:8080\n" + "Call log:\n - navigating to " + "\"https://www.quora.com/topic/Machine-Learning\"") + if name == "playwright_scraper": + from playwright.sync_api import Error, TimeoutError as PWTimeout + return Error(instant), PWTimeout("Page.goto: Timeout 60000ms exceeded.") + if name == "selenium_scraper": + from selenium.common.exceptions import (TimeoutException, + WebDriverException) + return (WebDriverException(instant), + TimeoutException("timeout: Timed out receiving message from renderer")) + return RuntimeError(instant), TimeoutError("Navigation Timeout Exceeded: 60000 ms exceeded.") + + +def _check_load_error_reported(name, engine): + """A navigation that fails instantly is logged with its reason and not + as a timeout; the reason reaches the outcome, credentials masked. + + The 2026-10-20 canary logged four "Timeout loading" lines 64 ms after + the navigation started, with no reason, and wrote a sidecar that said + page_load_timeout and nothing more.""" + import io + import logging + instant, timeout = _navigation_errors(name) + ok = True + for exc, label in ((instant, "Navigation failed loading"), + (timeout, "Timeout loading")): + stream = io.StringIO() + handler = logging.StreamHandler(stream) + engine.logger.addHandler(handler) + try: + oc, bought = _drive_engine(engine, "content", goto_raises=exc, + retries=2) + finally: + engine.logger.removeHandler(handler) + log = stream.getvalue() + first = str(exc).splitlines()[0].replace( + "canary-login" + ":" + "not-a-real-pass" + "@", "***:***@") + ok &= check(f"{name}: {type(exc).__name__} on every navigation -> " + f"load_failed with the reason on the outcome", + oc.load_failed and oc.load_error == first[:200] + and bought == 0) + ok &= check(f"{name}: {type(exc).__name__} is logged as " + f"'{label}' with its reason, and gives up naming it", + label in log and log.count(first[:200]) == 2 + and ("Timeout loading" in log) == (label == "Timeout loading")) + ok &= check(f"{name}: no credential in the log or the outcome", + "not-a-real-pass" not in log + (oc.load_error or "")) + return ok + + def _citation_tokens(): # Assembled from pieces so this file does not match its own guard. return ("CLAUDE" + ".md", "claude_" + "2scraper", "2scraper_" + "repo_rules", @@ -2404,6 +2469,7 @@ def test_audit_2026_10_14(skips): ok &= check(f"{name}: a 404 is not_found, not parsed, not blocked", oc.state == "not_found" and not oc.products and oc.blocked_by is None) + ok &= _check_load_error_reported(name, engine) # -- the engines map those states to the right stop reasons ------------- for name in ENGINES: @@ -2413,6 +2479,9 @@ def test_audit_2026_10_14(skips): src.count('stop_reason = "parser_found_nothing"') == 2) ok &= check(f"{name}: not_found has its own stop reason", 'stop_reason = "not_found"' in src) + ok &= check(f"{name}: the sidecar carries the first page's load_error", + '"load_error": next((o.load_error for o in outcomes ' + 'if o.load_error), None)' in src) ok &= check(f"{name}: the navigation status reaches the classifier", src.count("_classify(session.page, html, http_status)" if name == "playwright_scraper" else