From 976e0d9d3e613db4a0e05e5fa2b5e2e324107bfc Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Tue, 21 Jul 2026 18:37:47 +0000 Subject: [PATCH] fix(reports): fail-loud WARNING diagnostics and log-context tracing for tile readiness Companion to the previous commit's positive per-tile readiness check, carrying the rest of PR #42119's changes onto this base: - Per-tile readiness timeout logs at WARNING (customer chart-loading issue, not a system fault -- matching #38130/#38441) with elapsed wait time, tile index/total, load_wait, and the identity + stuck-state of each unready chart holder (waiting_on_database / spinner_mounted / nothing_mounted), then re-raises so the report fails rather than shipping a blank or spinner tile. A per-tile DEBUG line logs readiness wait time for profiling. - The deliberate readiness-timeout re-raise is tracked with an explicit flag rather than `except PlaywrightTimeout` at the outer level, since PlaywrightTimeout is aliased to bare Exception when playwright isn't installed and would otherwise swallow-or-propagate the wrong cases. - Threads an optional log_context (e.g. "execution_id=") from BaseReportState._get_screenshots through BaseScreenshot.get_screenshot and both WebDriverProxy implementations into take_tiled_screenshot, so timeout logs correlate back to the report run. Defaults to None for callers outside the report pipeline (thumbnails). Backported from apache/superset#42119 (commits 37da786b52, f6feb70eca, 97d15485ad squashed) onto this branch's base; only the log lines this change itself adds or touches carry the context suffix -- pre-existing log lines on this base (f-string style) are left as-is. Co-Authored-By: Claude --- superset/commands/report/execute.py | 4 +- superset/utils/screenshot_utils.py | 115 +++++++++++---- superset/utils/screenshots.py | 9 +- superset/utils/webdriver.py | 26 +++- .../reports/commands_tests.py | 4 +- .../unit_tests/utils/test_screenshot_utils.py | 132 ++++++++++++++++-- 6 files changed, 247 insertions(+), 43 deletions(-) diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 05cee434cd7..1010126e7ea 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -466,7 +466,9 @@ class BaseReportState: try: imges = [] for screenshot in screenshots: - if imge := screenshot.get_screenshot(user=user): + if imge := screenshot.get_screenshot( + user=user, log_context=f"execution_id={self._execution_id}" + ): imges.append(imge) elapsed_seconds = (datetime.utcnow() - start_time).total_seconds() logger.info( diff --git a/superset/utils/screenshot_utils.py b/superset/utils/screenshot_utils.py index a80c2c39bf2..204a5a29d9f 100644 --- a/superset/utils/screenshot_utils.py +++ b/superset/utils/screenshot_utils.py @@ -19,6 +19,7 @@ from __future__ import annotations import io import logging +import time from typing import TYPE_CHECKING from PIL import Image @@ -48,10 +49,22 @@ if TYPE_CHECKING: # See superset-frontend/src/dashboard/components/gridComponents/ChartHolder/ # ChartHolder.tsx for `data-test="dashboard-component-chart-holder"`, # superset-frontend/src/components/Chart/Chart.tsx for `.slice_container` -# (rendered chart container) and `.loading` (spinner, via the shared Loading -# component), and superset-frontend/packages/superset-ui-core/src/components/ -# EmptyState for `.ant-empty` (e.g. "no results"/"add required control -# values" states). +# (rendered chart container, `data-test="slice-container"`) and `.loading` +# (spinner, via the shared Loading component), and +# superset-frontend/packages/superset-ui-core/src/components/EmptyState for +# `.ant-empty` (e.g. "no results"/"add required control values" states). +# +# For diagnostics, each unready holder is additionally classified by *why* +# it isn't ready, distinguishing a slow query from the virtualization race: +# - "waiting_on_database": `.loading` present with no `.slice_container` +# -- Chart.tsx's `renderSpinner()` replaces the whole container while +# the initial query is in flight (`chartStatus === 'loading'`). +# - "spinner_mounted": `.loading` present *inside* `.slice_container` +# -- the chart's query finished, but it isn't in the virtualization +# viewport yet, so `renderChartContainer()` shows a bare spinner instead +# of the chart. +# - "nothing_mounted": neither `.loading` nor any ready marker present -- +# the vacuous-pass race this check exists to close. _UNREADY_CHART_HOLDERS_JS_BODY = """ const holders = document.querySelectorAll( '[data-test="dashboard-component-chart-holder"]' @@ -62,15 +75,29 @@ _UNREADY_CHART_HOLDERS_JS_BODY = """ if (!(r.top < window.innerHeight && r.bottom > 0)) { continue; } + const hasSliceContainer = holder.querySelector( + '[data-test="slice-container"]' + ) !== null; const stillLoading = holder.querySelector('.loading') !== null; - const isReady = holder.querySelector( - '.slice_container, [role="alert"], .ant-empty, .missing-chart-container' + const isReady = hasSliceContainer || holder.querySelector( + '[role="alert"], .ant-empty, .missing-chart-container' ) !== null; if (stillLoading || !isReady) { const chartIdEl = holder.querySelector('[data-test-chart-id]'); - unready.push( - chartIdEl ? chartIdEl.getAttribute('data-test-chart-id') : 'unknown' - ); + let state; + if (stillLoading && hasSliceContainer) { + state = 'spinner_mounted'; + } else if (stillLoading) { + state = 'waiting_on_database'; + } else { + state = 'nothing_mounted'; + } + unready.push({ + chartId: chartIdEl + ? chartIdEl.getAttribute('data-test-chart-id') + : 'unknown', + state: state, + }); } } """ @@ -81,8 +108,8 @@ _TILE_READY_CHECK_JS = ( f"() => {{ {_UNREADY_CHART_HOLDERS_JS_BODY} return unready.length === 0; }}" ) -# Diagnostic query for page.evaluate: identities of chart holders (by -# data-test-chart-id) still not ready, used to build the timeout log message. +# Diagnostic query for page.evaluate: chart id + state of holders still not +# ready, used to build the timeout log message. _FIND_UNREADY_CHART_HOLDERS_JS = ( f"() => {{ {_UNREADY_CHART_HOLDERS_JS_BODY} return unready; }}" ) @@ -138,6 +165,7 @@ def take_tiled_screenshot( tile_height: int, load_wait: int = 60, animation_wait: int = 0, + log_context: str | None = None, ) -> bytes | None: """ Take a tiled screenshot of a large dashboard by scrolling and capturing sections. @@ -148,10 +176,24 @@ def take_tiled_screenshot( tile_height: Height of each tile in pixels load_wait: Seconds to wait for charts to load per tile (default 60) animation_wait: Seconds to wait for chart animations per tile (default 0) + log_context: Optional identifier (e.g. report execution id, or a + cache key for thumbnails) appended to log lines so a slow/timed-out + capture can be traced back to the run that produced it. Returns: Combined screenshot bytes or None if failed """ + context_suffix = f" [{log_context}]" if log_context else "" + # Set right before re-raising the per-tile readiness timeout below, and + # checked in the except block at the bottom of this function. Deciding + # whether to propagate via `isinstance(e, PlaywrightTimeout)` would be + # unreliable: when the playwright package isn't installed, + # `PlaywrightTimeout` is aliased to the bare `Exception` class (see the + # try/except ImportError above this function), which would make *any* + # exception -- not just our own deliberate readiness-timeout raise -- + # match `except PlaywrightTimeout` and incorrectly propagate instead of + # degrading to `None` like every other unexpected error in this function. + readiness_timeout = False try: # Get the target element element = page.locator(f".{element_name}") @@ -201,25 +243,45 @@ def take_tiled_screenshot( # placeholders rendered for off-screen charts. A holder that hasn't # mounted anything yet does not satisfy this check -- unlike checking # for the absence of `.loading`, which passes vacuously in that case. + tile_wait_start = time.monotonic() try: page.wait_for_function( _TILE_READY_CHECK_JS, timeout=load_wait * 1000, ) except PlaywrightTimeout: - unready_chart_ids = page.evaluate(_FIND_UNREADY_CHART_HOLDERS_JS) - logger.error( - "Timed out waiting for %s chart container(s) to become ready " - "on tile %s/%s (load_wait=%ss); unready chart ids: %s. " - "Aborting tiled screenshot rather than capturing a blank or " - "partially-loaded tile.", - len(unready_chart_ids), + elapsed = time.monotonic() - tile_wait_start + unready_chart_holders = page.evaluate(_FIND_UNREADY_CHART_HOLDERS_JS) + # A chart failing to load in time is a customer chart-loading + # issue (slow query, error state, etc.), not a Superset system + # fault, so this stays at WARNING -- the report still fails + # loudly via the `raise` below. See #38130 / #38441, which + # made the same call for the other screenshot timeout paths. + logger.warning( + "Timed out after %.2fs waiting for %s chart container(s) to " + "become ready on tile %s/%s (load_wait=%ss)%s; unready chart " + "holders (chart id, state): %s. Aborting tiled screenshot " + "rather than capturing a blank or partially-loaded tile.", + elapsed, + len(unready_chart_holders), i + 1, num_tiles, load_wait, - unready_chart_ids, + context_suffix, + unready_chart_holders, ) + readiness_timeout = True raise + else: + elapsed = time.monotonic() - tile_wait_start + logger.debug( + "Tile %s/%s chart holders ready after %.2fs (load_wait=%ss)%s", + i + 1, + num_tiles, + elapsed, + load_wait, + context_suffix, + ) # Wait for chart animations (e.g. ECharts) to finish after spinner clears. # The global animation wait before tiling only covers the first tile; @@ -274,10 +336,15 @@ def take_tiled_screenshot( return combined_screenshot - except PlaywrightTimeout: - # Let per-tile readiness timeouts propagate so the caller fails the - # report instead of silently falling back to a degraded screenshot. - raise except Exception as e: - logger.exception(f"Tiled screenshot failed: {e}") + if readiness_timeout: + # Let the per-tile readiness timeout propagate so the caller + # fails the report instead of silently falling back to a + # degraded screenshot -- already logged as a WARNING above. + raise + # Any other exception is a genuine system-level fault (or a setup + # failure unrelated to chart readiness, e.g. the dashboard element + # itself never appearing), not a customer chart taking too long to + # load, so it stays at ERROR/exception level. + logger.exception("Tiled screenshot failed: %s%s", e, context_suffix) return None diff --git a/superset/utils/screenshots.py b/superset/utils/screenshots.py index 3c48c3e2d46..897d9067b1d 100644 --- a/superset/utils/screenshots.py +++ b/superset/utils/screenshots.py @@ -207,10 +207,15 @@ class BaseScreenshot: return WebDriverSelenium(self.driver_type, window_size) def get_screenshot( - self, user: User, window_size: WindowSize | None = None + self, + user: User, + window_size: WindowSize | None = None, + log_context: str | None = None, ) -> bytes | None: driver = self.driver(window_size) - self.screenshot = driver.get_screenshot(self.url, self.element, user) + self.screenshot = driver.get_screenshot( + self.url, self.element, user, log_context=log_context + ) return self.screenshot def get_cache_key( diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index d640d9476f1..44dbcb5ed17 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -159,9 +159,18 @@ class WebDriverProxy(ABC): self._screenshot_load_wait = app.config["SCREENSHOT_LOAD_WAIT"] @abstractmethod - def get_screenshot(self, url: str, element_name: str, user: User) -> bytes | None: + def get_screenshot( + self, + url: str, + element_name: str, + user: User, + log_context: str | None = None, + ) -> bytes | None: """ Run webdriver and return a screenshot + + :param log_context: Optional identifier (e.g. report execution id, or + a cache key for thumbnails) included in log lines for tracing. """ @@ -224,7 +233,11 @@ class WebDriverPlaywright(WebDriverProxy): return element.screenshot() def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # noqa: C901 - self, url: str, element_name: str, user: User + self, + url: str, + element_name: str, + user: User, + log_context: str | None = None, ) -> bytes | None: if not PLAYWRIGHT_AVAILABLE: logger.info( @@ -361,6 +374,7 @@ class WebDriverPlaywright(WebDriverProxy): tile_height, load_wait=self._screenshot_load_wait, animation_wait=selenium_animation_wait, + log_context=log_context, ) if not img: logger.warning( @@ -679,7 +693,13 @@ class WebDriverSelenium(WebDriverProxy): return error_messages - def get_screenshot(self, url: str, element_name: str, user: User) -> bytes | None: # noqa: C901 + def get_screenshot( # noqa: C901 + self, + url: str, + element_name: str, + user: User, + log_context: str | None = None, + ) -> bytes | None: driver = self.auth(user) driver.set_window_size(*self._window) driver.get(url) diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index ae1c855d85a..40f8ee77444 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -782,7 +782,9 @@ def test_email_chart_report_schedule_alpha_owner( # setup screenshot mock username = "" - def _screenshot_side_effect(user: User) -> Optional[bytes]: + def _screenshot_side_effect( + user: User, log_context: Optional[str] = None + ) -> Optional[bytes]: nonlocal username username = user.username diff --git a/tests/unit_tests/utils/test_screenshot_utils.py b/tests/unit_tests/utils/test_screenshot_utils.py index f0f0c28267e..0a9823c3c8f 100644 --- a/tests/unit_tests/utils/test_screenshot_utils.py +++ b/tests/unit_tests/utils/test_screenshot_utils.py @@ -195,10 +195,32 @@ class TestTakeTiledScreenshot: result = take_tiled_screenshot(mock_page, "dashboard", tile_height=2000) assert result is None - mock_logger.exception.assert_called_once_with( - "Tiled screenshot failed: Unexpected error" + # The exception object is passed, not the string + call_args = mock_logger.exception.call_args + assert call_args[0][0] == "Tiled screenshot failed: %s%s" + assert str(call_args[0][1]) == "Unexpected error" + assert call_args[0][2] == "" # no log_context passed + + def test_exception_handling_logs_context(self): + """Genuine system faults (not a customer chart-loading issue) stay at + ERROR/exception level, and still carry the log context (e.g. report + execution id) for correlation with the run that triggered this + screenshot.""" + mock_page = MagicMock() + mock_page.locator.side_effect = Exception("Unexpected error") + + with patch("superset.utils.screenshot_utils.logger") as mock_logger: + result = take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + log_context="execution_id=abc-123", ) + assert result is None + call_args = mock_logger.exception.call_args + assert call_args[0][2] == " [execution_id=abc-123]" + def test_screenshot_clip_parameters(self, mock_page): """Test that screenshot clipping parameters are correct.""" with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): @@ -350,7 +372,7 @@ class TestTakeTiledScreenshot: mock_page.evaluate.side_effect = [ {"height": 5000, "top": 100, "left": 50, "width": 800}, # dimensions None, # window.scrollTo(...) for tile 1 - ["42"], # unready chart ids, gathered after the timeout + [{"chartId": "42", "state": "waiting_on_database"}], # diagnostics ] with patch("superset.utils.screenshot_utils.logger") as mock_logger: @@ -368,14 +390,51 @@ class TestTakeTiledScreenshot: # aborts before any subsequent tile is processed). assert mock_page.wait_for_function.call_count == 1 - mock_logger.error.assert_called_once() - error_args = mock_logger.error.call_args[0] - assert "unready" in error_args[0].lower() - assert error_args[1] == 1 # count of unready chart containers - assert error_args[2] == 1 # tile index - assert error_args[3] == 3 # total tiles - assert error_args[4] == 30 # load_wait - assert error_args[5] == ["42"] + # A chart failing to load in time is a customer chart-loading issue, + # not a Superset system fault -- WARNING, not ERROR (#38130, #38441). + # The report still fails loudly via the raise, asserted above. + mock_logger.error.assert_not_called() + mock_logger.warning.assert_called_once() + warning_args = mock_logger.warning.call_args[0] + assert "unready" in warning_args[0].lower() + elapsed = warning_args[1] + assert isinstance(elapsed, float) + assert elapsed >= 0 + assert warning_args[2] == 1 # count of unready chart containers + assert warning_args[3] == 1 # tile index + assert warning_args[4] == 3 # total tiles + assert warning_args[5] == 30 # load_wait + assert warning_args[6] == "" # no log_context passed + # Diagnostic payload identifies chart id AND the state it's stuck in + # (spinner mounted vs nothing mounted vs waiting-on-database) so a + # slow query can be told apart from the virtualization race. + assert warning_args[7] == [{"chartId": "42", "state": "waiting_on_database"}] + + def test_timeout_warning_includes_log_context(self, mock_page): + """The log context (e.g. report execution id) is threaded through for + correlation with the run that triggered this screenshot.""" + from superset.utils.screenshot_utils import PlaywrightTimeout + + mock_page.wait_for_function.side_effect = PlaywrightTimeout("timed out") + mock_page.evaluate.side_effect = [ + {"height": 2000, "top": 0, "left": 0, "width": 800}, + None, + [{"chartId": "7", "state": "nothing_mounted"}], + ] + + with patch("superset.utils.screenshot_utils.logger") as mock_logger: + with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): + with pytest.raises(PlaywrightTimeout): + take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + load_wait=5, + log_context="execution_id=abc-123", + ) + + warning_args = mock_logger.warning.call_args[0] + assert warning_args[6] == " [execution_id=abc-123]" def test_chart_holder_with_nothing_mounted_blocks_wait(self, mock_page): """Regression test for the vacuous-pass race (PR #39895). @@ -399,7 +458,7 @@ class TestTakeTiledScreenshot: mock_page.evaluate.side_effect = [ {"height": 2000, "top": 0, "left": 0, "width": 800}, # dimensions None, # window.scrollTo(...) for tile 1 - ["7"], # the un-mounted holder's chart id + [{"chartId": "7", "state": "nothing_mounted"}], # diagnostics ] with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): @@ -411,6 +470,55 @@ class TestTakeTiledScreenshot: assert js_call_count["n"] == 1 mock_page.screenshot.assert_not_called() + def test_unready_holder_state_classification_embedded_in_js(self, mock_page): + """The readiness JS classifies *why* a holder isn't ready. + + Distinguishing "spinner_mounted" (query done, not yet in the + virtualization viewport), "waiting_on_database" (initial query still + in flight), and "nothing_mounted" (the vacuous-pass race) is what + lets a slow query be told apart from the race during an incident. + """ + from superset.utils.screenshot_utils import ( + _FIND_UNREADY_CHART_HOLDERS_JS, + _TILE_READY_CHECK_JS, + ) + + for js in (_TILE_READY_CHECK_JS, _FIND_UNREADY_CHART_HOLDERS_JS): + assert "spinner_mounted" in js + assert "waiting_on_database" in js + assert "nothing_mounted" in js + assert "slice-container" in js + + def test_per_tile_timing_logged_at_debug(self, mock_page): + """Each tile logs how long it waited for readiness, for profiling.""" + with patch("superset.utils.screenshot_utils.logger") as mock_logger: + with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): + take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + load_wait=30, + log_context="execution_id=abc-123", + ) + + # 3 tiles, all ready immediately (mock_page.wait_for_function is a + # no-op MagicMock by default) -> one timing line per tile. + timing_calls = [ + call + for call in mock_logger.debug.call_args_list + if "ready after" in call[0][0] + ] + assert len(timing_calls) == 3 + + first_call_args = timing_calls[0][0] + assert first_call_args[1] == 1 # tile index + assert first_call_args[2] == 3 # total tiles + elapsed = first_call_args[3] + assert isinstance(elapsed, float) + assert elapsed >= 0 + assert first_call_args[4] == 30 # load_wait + assert first_call_args[5] == " [execution_id=abc-123]" + def test_all_chart_holders_ready_passes(self, mock_page): """All chart holders rendered or errored -> wait passes, tile captured.""" with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"):