diff --git a/.github/workflows/test-stack-reusable-workflow.yml b/.github/workflows/test-stack-reusable-workflow.yml index dae9e9dd7..42678f54d 100644 --- a/.github/workflows/test-stack-reusable-workflow.yml +++ b/.github/workflows/test-stack-reusable-workflow.yml @@ -205,7 +205,7 @@ jobs: # keeps the run short. Each file is wrapped in its own log group and the failing one is # named explicitly, because everything after it is SKIPPED rather than run, and that is # otherwise easy to misread as "the whole browser suite broke". - for t in tests/fetchers/test_content.py tests/test_errorhandling.py tests/visualselector/test_fetch_data.py tests/fetchers/test_custom_js_before_content.py; do + for t in tests/fetchers/test_content.py tests/test_errorhandling.py tests/visualselector/test_fetch_data.py tests/fetchers/test_custom_js_before_content.py tests/fetchers/test_renavigation.py; do echo "::group::pytest $t" if ! docker run --rm -e "FLASK_SERVER_NAME=cdio" -e "PLAYWRIGHT_DRIVER_URL=ws://sockpuppetbrowser:3000" --network changedet-network --hostname=cdio test-changedetectionio \ bash -c "cd changedetectionio;pytest -vv --capture=tee-sys --showlocals --tb=long --live-server-host=0.0.0.0 --live-server-port=5004 $t"; then @@ -253,7 +253,7 @@ jobs: - name: Pyppeteer - Specific tests in built container run: | # Fail fast, but name the file that failed - see the note in the playwright job above - for t in tests/fetchers/test_content.py tests/test_errorhandling.py tests/visualselector/test_fetch_data.py tests/fetchers/test_custom_js_before_content.py; do + for t in tests/fetchers/test_content.py tests/test_errorhandling.py tests/visualselector/test_fetch_data.py tests/fetchers/test_custom_js_before_content.py tests/fetchers/test_renavigation.py; do echo "::group::pytest $t" if ! docker run --rm -e "FLASK_SERVER_NAME=cdio" -e "FAST_PUPPETEER_CHROME_FETCHER=True" -e "PLAYWRIGHT_DRIVER_URL=ws://sockpuppetbrowser:3000" --network changedet-network --hostname=cdio test-changedetectionio \ bash -c "cd changedetectionio;pytest --live-server-host=0.0.0.0 --live-server-port=5004 $t"; then diff --git a/changedetectionio/content_fetchers/playwright.py b/changedetectionio/content_fetchers/playwright.py index f20981dff..e21df27ba 100644 --- a/changedetectionio/content_fetchers/playwright.py +++ b/changedetectionio/content_fetchers/playwright.py @@ -296,6 +296,20 @@ class fetcher(Fetcher): self.page = await context.new_page() + # Track the LATEST main-frame document response for the whole fetch, not just the one + # goto() returns. This app compares the text of the page the browser ends up on, and a + # site that gates with an interstitial (503/429 + meta-refresh) navigates to the real + # page *during* the extra_wait below - judging the fetch on the first response fails a + # watch whose content is present and fine. Same for plain client-side redirects. + # Shared with action_goto_url() so only one 'response' listener exists on the page. + from changedetectionio.browser_steps.browser_steps import track_latest_navigation_response + # Must be an identity check - the tracker hands back the same (initially empty, so + # falsy) dict the listener writes into, and `or {}` would quietly swap in a different + # one that never gets updated. + latest_navigation_response = track_latest_navigation_response(self.page) + if latest_navigation_response is None: + latest_navigation_response = {} + # Listen for all console events and handle errors self.page.on("console", lambda msg: logger.debug(f"Playwright console: Watch URL: {url} {msg.type}: {msg.text} {msg.args}")) @@ -336,6 +350,25 @@ class fetcher(Fetcher): extra_wait = int(os.getenv("WEBDRIVER_DELAY_BEFORE_CONTENT_READY", 5)) + self.render_extract_delay await self.page.wait_for_timeout(extra_wait * 1000) + # A meta-refresh or client-side redirect usually lands during that wait, so judge the + # fetch on the document we are actually about to extract rather than the first one. + latest = latest_navigation_response.get('response') + if latest is not None and latest is not response: + logger.debug(f"Page navigated again while waiting, judging the fetch on {latest.url} " + f"(status {latest.status}) instead of the first response for {url}") + response = latest + try: + self.headers = await response.all_headers() + except Exception as e: + logger.debug(f"Could not refresh headers from the final document: {e}") + + # Don't extract while a navigation is mid-flight, that is what produces + # "Execution context was destroyed, most likely because of a navigation" + try: + await self.page.wait_for_load_state('load', timeout=extra_wait * 1000) + except Exception as e: + logger.debug(f"Page did not reach a settled load state, continuing anyway: {e}") + try: self.status_code = response.status except Exception as e: diff --git a/changedetectionio/content_fetchers/puppeteer.py b/changedetectionio/content_fetchers/puppeteer.py index 6e9acbb1a..13e9ee0d0 100644 --- a/changedetectionio/content_fetchers/puppeteer.py +++ b/changedetectionio/content_fetchers/puppeteer.py @@ -399,43 +399,69 @@ class fetcher(Fetcher): # Enable Network domain to detect when first bytes arrive await self.page._client.send('Network.enable') - # Now set up the frame navigation handlers - async def handle_frame_navigation(event=None): - # Wait n seconds after the frameStartedLoading, not from any frameStartedLoading/frameStartedNavigating - logger.debug(f"Frame navigated: {event}") - w = extra_wait - 2 if extra_wait > 4 else 2 - logger.debug(f"Waiting {w} seconds before calling Page.stopLoading...") - await asyncio.sleep(w) + # Navigate (bounded), then wait the configured "wait n seconds before extracting text" + # delay, then stop whatever is still loading, then extract. The delay is measured from + # when navigation finished, not from when it started, because the point of it is to let + # JS-rendered content appear *after* load - anchoring it to the start would quietly give a + # slow-loading page almost no settle time. + # + # Only that delay is a user-facing setting. The navigation bound above is a safety net with + # a sane default, not a tuning knob, so there is still one number for users to think about. + # + # There is no way to know a page is "finished" - plenty of sites navigate as part of their + # normal design, and some sit forever on a subresource that never answers. So the delay + # restarts if the MAIN frame replaces its document (a redirect or interstitial gets the + # same settle time the first document got), iframes do not restart it, and it is capped so + # a page that re-navigates in a loop cannot extend it indefinitely. + max_content_ready_resets = int(os.getenv("BROWSER_CONTENT_READY_MAX_RESETS", 2)) - # Check if page still exists (might have been closed due to error during sleep) - if not self.page or not hasattr(self.page, '_client'): - logger.debug("Page already closed, skipping stopLoading") - return + async def wait_for_content_ready_then_stop_loading(): + main_frame_id = self.page.mainFrame._id + renavigated = asyncio.Event() - logger.debug("Issuing stopLoading command...") - await self.page._client.send('Page.stopLoading') - logger.debug("stopLoading command sent!") + def _on_main_frame_navigation(event): + if event.get('frameId') == main_frame_id: + renavigated.set() - async def setup_frame_handlers_on_first_response(event): - # Only trigger for the main document response - if event.get('type') == 'Document': - logger.debug("First response received, setting up frame handlers for forced page stop load.") - self.page._client.on('Page.frameStartedNavigating', lambda e: asyncio.create_task(handle_frame_navigation(e))) - self.page._client.on('Page.frameStartedLoading', lambda e: asyncio.create_task(handle_frame_navigation(e))) - self.page._client.on('Page.frameStoppedLoading', lambda e: logger.debug(f"Frame stopped loading: {e}")) - logger.debug("First response received, setting up frame handlers for forced page stop load DONE SETUP") - # De-register this listener - we only need it once - self.page._client.remove_listener('Network.responseReceived', setup_frame_handlers_on_first_response) + self.page._client.on('Page.frameStartedLoading', _on_main_frame_navigation) + self.page._client.on('Page.frameStoppedLoading', lambda e: logger.debug(f"Frame stopped loading: {e}")) + try: + resets = 0 + while True: + renavigated.clear() + try: + await asyncio.wait_for(renavigated.wait(), timeout=extra_wait) + # Main frame started a new document + resets += 1 + if resets > max_content_ready_resets: + logger.debug(f"Main frame keeps re-navigating, not restarting the content-ready wait again") + break + logger.debug(f"Main frame started a new document, restarting the {extra_wait}s " + f"content-ready wait ({resets}/{max_content_ready_resets})") + except asyncio.TimeoutError: + # Quiet for the whole delay - the page is as ready as it is going to get + break + finally: + self.page._client.remove_listener('Page.frameStartedLoading', _on_main_frame_navigation) - # Listen for first response to trigger frame handler setup - self.page._client.on('Network.responseReceived', setup_frame_handlers_on_first_response) + # Stop whatever is still in flight so the DOM and screenshot come from what rendered, + # rather than waiting on a subresource that may never answer + try: + logger.debug(f"Content-ready wait of {extra_wait}s elapsed, issuing Page.stopLoading before extracting") + await self.page._client.send('Page.stopLoading') + logger.debug("stopLoading command sent!") + except Exception as e: + logger.debug(f"Page.stopLoading skipped, page is most likely already gone: {e}") - # Chrome 153+ refuses to commit a navigation when an error status arrives with a - # zero-length body, so goto() raises net::ERR_HTTP_RESPONSE_CODE_FAILURE instead of handing - # back the response. The response was received fine, we just never get it as a return value, - # so keep the main-frame response from the 'response' event and use that instead - the - # status check below then reports a real "Error - 404" instead of a raw net:: string. - # Kept as the latest matching response so a redirect chain reports its final hop. + # Track the LATEST main-frame document response for the whole fetch, not just the one that + # goto() happens to return. This app compares the text of the page the browser ends up on, + # and plenty of sites navigate again after the first response: + # - an interstitial answering 503/429 with a meta-refresh into the real 200 page, where + # judging the first response fails a watch whose content is sitting right there + # - a plain client-side redirect to another host (slated.com -> get.slated.com) + # It also covers Chrome 153+, which refuses to commit a navigation when an error status + # arrives with a zero-length body: goto() raises net::ERR_HTTP_RESPONSE_CODE_FAILURE rather + # than returning the response, but the response itself still arrives on this event. navigation_response = {} def _keep_navigation_response(response): @@ -445,25 +471,62 @@ class fetcher(Fetcher): self.page.on('response', _keep_navigation_response) + # pyppeteer's navigation watcher is bound to the loaderId of the navigation it started. If + # the page replaces that document (redirect/interstitial) the 'load' it waits for never + # arrives for that loaderId, so goto() never returns - and with timeout=0 it would block + # until the hard PUPPETEER_MAX_PROCESSING_TIMEOUT_SECONDS kill, burning a worker slot for + # minutes on a page that is fully loaded. Bound it, then fall back to the document we can + # see. Verified against slated.com and getastra.com, which hang indefinitely otherwise. + nav_timeout = int(os.getenv("BROWSER_NAVIGATION_TIMEOUT_SECONDS", 30)) + response = None attempt=0 try: while not response: logger.debug(f"Attempting page fetch {url} attempt {attempt}") - asyncio.create_task(handle_frame_navigation()) - try: - response = await self.page.goto(url, timeout=0) - except Exception as e: - if 'ERR_HTTP_RESPONSE_CODE_FAILURE' not in str(e) or not navigation_response: - raise - response = navigation_response['response'] - logger.debug(f"Navigation was aborted by the browser (empty body on an error status), " - f"recovered status {response.status} from the response event") - await asyncio.sleep(1 + extra_wait) - # Check if page still exists before sending command - if self.page and hasattr(self.page, '_client'): - await self.page._client.send('Page.stopLoading') + # Race goto() against the main frame actually firing 'load'. In the re-navigation + # case goto() can never resolve, but the replacement document does fire 'load' - + # usually within a few seconds - so this returns then instead of sitting out the + # whole nav_timeout. Whichever arrives first means "the document is loaded". + main_frame_loaded = asyncio.Event() + main_frame_id = self.page.mainFrame._id + def _on_lifecycle(event): + if event.get('name') == 'load' and event.get('frameId') == main_frame_id: + main_frame_loaded.set() + + self.page._client.on('Page.lifecycleEvent', _on_lifecycle) + goto_task = asyncio.ensure_future(self.page.goto(url, timeout=0)) + load_task = asyncio.ensure_future(main_frame_loaded.wait()) + try: + done, _pending = await asyncio.wait({goto_task, load_task}, + timeout=nav_timeout, + return_when=asyncio.FIRST_COMPLETED) + + if goto_task in done: + try: + response = goto_task.result() + except Exception as e: + if 'ERR_HTTP_RESPONSE_CODE_FAILURE' not in str(e) or not navigation_response: + raise + response = navigation_response['response'] + logger.debug(f"Navigation was aborted by the browser (empty body on an error status), " + f"recovered status {response.status} from the response event") + else: + # Either the replacement document loaded, or we ran out of patience + response = navigation_response.get('response') + if not response: + raise BrowserFetchTimedOut(msg=f"Browser did not finish navigating to {url} within " + f"{nav_timeout}s and no main-frame response was seen.") + why = ("the page replaced the document it started on" if load_task in done + else f"navigation did not settle within {nav_timeout}s") + logger.warning(f"Continuing with the document actually loaded ({why}) - " + f"status {response.status} for {response.url}") + finally: + self.page._client.remove_listener('Page.lifecycleEvent', _on_lifecycle) + for t in (goto_task, load_task): + if not t.done(): + t.cancel() if response: break if not response: @@ -472,6 +535,19 @@ class fetcher(Fetcher): logger.warning(f"Content Fetcher > Response object was none (as in, the response from the browser was empty, not just the content) exiting attempt {attempt}") raise EmptyReply(url=url, status_code=None) attempt+=1 + + # Navigation is done; now honour "wait n seconds before extracting text" and then + # force-stop whatever is still loading, so extraction always gets what rendered. + # Awaited inline rather than fired off as a task, so nothing can outlive the fetch. + await wait_for_content_ready_then_stop_loading() + + # That wait is where a meta-refresh interstitial typically swaps in the real page, so + # re-check which document we are actually on before judging the status code. + latest = navigation_response.get('response') + if latest is not None and latest is not response: + logger.debug(f"Page navigated again while waiting, judging the fetch on {latest.url} " + f"(status {latest.status}) instead of {response.url} (status {response.status})") + response = latest finally: self.page.remove_listener('response', _keep_navigation_response) diff --git a/changedetectionio/tests/fetchers/test_renavigation.py b/changedetectionio/tests/fetchers/test_renavigation.py new file mode 100644 index 000000000..ba3bc4231 --- /dev/null +++ b/changedetectionio/tests/fetchers/test_renavigation.py @@ -0,0 +1,60 @@ +#!/usr/bin/env python3 + +"""The browser fetchers must judge a fetch on the document they end up extracting. + +Plenty of sites answer the first request with an interstitial carrying an error status and a +client-side redirect, then serve the real page. Judging the fetch on the first navigation fails a +watch whose content is present and fine (reported against fotokoch.de: 503 + meta refresh -> 200), +and on the pyppeteer fetcher a replaced document used to hang goto() until the hard processing +timeout because its navigation watcher is bound to the loaderId it started on. +""" + +import os +from flask import url_for +from ..util import wait_for_all_checks + + +def _cdio(url): + # The browser runs in another container in CI and reaches the test server as 'cdio' + return url.replace('localhost.localdomain', 'cdio').replace('localhost', 'cdio') + + +def test_interstitial_redirect_is_followed(client, live_server, measure_memory_usage, datastore_path): + assert os.getenv('PLAYWRIGHT_DRIVER_URL'), "Needs PLAYWRIGHT_DRIVER_URL set for this test" + + res = client.post( + url_for("settings.settings_page"), + data={ + "application-empty_pages_are_a_change": "", + "requests-time_between_check-minutes": 180, + 'application-fetch_backend': "html_webdriver", + }, + follow_redirects=True + ) + assert b"Settings updated." in res.data + + test_url = _cdio(url_for('test_interstitial', key='renav', _external=True)) + + res = client.post( + url_for("imports.import_page"), + data={"urls": test_url}, + follow_redirects=True + ) + assert b"1 Imported" in res.data + wait_for_all_checks(client) + + # The interstitial answered 503, so judging the first navigation would have failed the watch + uuid = next(iter(live_server.app.config['DATASTORE'].data['watching'])) + watch = live_server.app.config['DATASTORE'].data['watching'][uuid] + assert not watch.get('last_error'), \ + f"Watch was judged on the interstitial instead of the page it landed on: {watch.get('last_error')}" + + res = client.get(url_for("watchlist.index")) + assert b'Error - 503' not in res.data + + assert watch.history_n >= 1, "Fetch succeeded but no snapshot was stored" + snapshot = watch.get_history_snapshot(list(watch.history.keys())[-1]) + assert 'The real page content is here' in snapshot + assert 'Browser check in progress' not in snapshot + + client.post(url_for("ui.form_delete", uuid="all"), follow_redirects=True) diff --git a/changedetectionio/tests/util.py b/changedetectionio/tests/util.py index 6c30aeba1..dfcf4582c 100644 --- a/changedetectionio/tests/util.py +++ b/changedetectionio/tests/util.py @@ -249,6 +249,31 @@ def new_live_server_setup(live_server): import secrets return "Random content - {}\n".format(secrets.token_hex(64)) + # Re-navigation gate: the first hit answers with an error status AND a client-side meta + # refresh, the second serves the real page. This mirrors sites that gate visitors they have + # not seen recently (reported against fotokoch.de, which answers 503 + meta refresh and then + # serves a 200). The browser follows the refresh, so the fetch has to be judged on the + # document we actually end up extracting rather than on the interstitial. + # Keyed on last-seen time rather than a hit count, so EVERY fresh check starts out gated - + # a counter would serve a clean 200 to the second check and let the test pass without the fix. + _interstitial_last_seen = {} + + @live_server.app.route('/test-interstitial') + def test_interstitial(): + key = request.args.get('key', 'default') + now = time.time() + seen_recently = (now - _interstitial_last_seen.get(key, 0)) < 10 + _interstitial_last_seen[key] = now + if not seen_recently: + resp = make_response( + '' + 'Browser check in progress, you will be redirected', 503) + else: + resp = make_response( + '

The real page content is here

', 200) + resp.headers['Content-Type'] = 'text/html' + return resp + @live_server.app.route('/test-endpoint2') def test_endpoint2(): return "some basic content"