diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 50cfe33af0b..defbd32dde7 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -563,7 +563,9 @@ class BaseReportState: try: imges = [] for screenshot in screenshots: - imge = screenshot.get_screenshot(user=user) + imge = screenshot.get_screenshot( + user=user, execution_id=str(self._execution_id) + ) if imge is None: raise ReportScheduleScreenshotFailedError( "Screenshot failed; aborting to avoid sending a partial report" diff --git a/superset/utils/screenshot_utils.py b/superset/utils/screenshot_utils.py index 36e8b7db2c2..69eac3a570f 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, + execution_id: str | None = None, ) -> bytes | None: """ Take a tiled screenshot of a large dashboard by scrolling and capturing sections. @@ -148,10 +176,14 @@ 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) + execution_id: Report execution id, included in log lines for + correlation with the report that triggered this screenshot. + None for callers outside the report pipeline (e.g. thumbnails). Returns: Combined screenshot bytes or None if failed """ + exec_id_suffix = f" - execution_id: {execution_id}" if execution_id else "" try: # Get the target element element = page.locator(f".{element_name}") @@ -204,25 +236,44 @@ 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, + exec_id_suffix, + unready_chart_holders, ) 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, + exec_id_suffix, + ) # Wait for chart animations (e.g. ECharts) to finish after spinner clears. # The global animation wait before tiling only covers the first tile; @@ -282,5 +333,8 @@ def take_tiled_screenshot( # report instead of silently falling back to a degraded screenshot. raise except Exception as e: - logger.exception("Tiled screenshot failed: %s", e) + # Unlike the readiness-timeout warning above, this is a genuine + # system-level fault (unexpected error, not a customer chart taking + # too long to load), so it stays at ERROR/exception level. + logger.exception("Tiled screenshot failed: %s%s", e, exec_id_suffix) return None diff --git a/superset/utils/screenshots.py b/superset/utils/screenshots.py index 4107e98d7ed..c16fc960638 100644 --- a/superset/utils/screenshots.py +++ b/superset/utils/screenshots.py @@ -210,11 +210,16 @@ class BaseScreenshot: return WebDriverSelenium(self.driver_type, window_size, user) def get_screenshot( - self, user: User, window_size: WindowSize | None = None + self, + user: User, + window_size: WindowSize | None = None, + execution_id: str | None = None, ) -> bytes | None: driver = self.driver(window_size, user) try: - self.screenshot = driver.get_screenshot(self.url, self.element, user) + self.screenshot = driver.get_screenshot( + self.url, self.element, user, execution_id=execution_id + ) finally: if isinstance(driver, WebDriverSelenium): driver.destroy() diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index 505223fd2ae..98f4c7efcc5 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -203,10 +203,17 @@ class WebDriverProxy(ABC): @abstractmethod def get_screenshot( - self, url: str, element_name: str, user: User | None = None + self, + url: str, + element_name: str, + user: User | None = None, + execution_id: str | None = None, ) -> bytes | None: """ Run webdriver and return a screenshot + + :param execution_id: Report execution id, for log correlation. None + for callers outside the report pipeline (e.g. thumbnails). """ @@ -269,7 +276,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 | None = None + self, + url: str, + element_name: str, + user: User | None = None, + execution_id: str | None = None, ) -> bytes | None: if not PLAYWRIGHT_AVAILABLE: logger.info( @@ -405,6 +416,7 @@ class WebDriverPlaywright(WebDriverProxy): tile_height, load_wait=self._screenshot_load_wait, animation_wait=selenium_animation_wait, + execution_id=execution_id, ) if not img: logger.warning( @@ -784,7 +796,11 @@ class WebDriverSelenium(WebDriverProxy): return error_messages def get_screenshot( # noqa: C901 - self, url: str, element_name: str, user: User | None = None + self, + url: str, + element_name: str, + user: User | None = None, + execution_id: str | None = None, ) -> bytes | None: # If a user is passed explicitly and differs from the stored user, # update and re-authenticate diff --git a/tests/unit_tests/utils/test_screenshot_utils.py b/tests/unit_tests/utils/test_screenshot_utils.py index dd4bec6bede..b88b3e7093e 100644 --- a/tests/unit_tests/utils/test_screenshot_utils.py +++ b/tests/unit_tests/utils/test_screenshot_utils.py @@ -199,8 +199,25 @@ class TestTakeTiledScreenshot: assert result is None # The exception object is passed, not the string call_args = mock_logger.exception.call_args - assert call_args[0][0] == "Tiled screenshot failed: %s" + assert call_args[0][0] == "Tiled screenshot failed: %s%s" assert str(call_args[0][1]) == "Unexpected error" + assert call_args[0][2] == "" # no execution_id passed + + def test_exception_handling_logs_execution_id(self): + """Genuine system faults (not a customer chart-loading issue) stay at + ERROR/exception level, and still carry the execution id for + correlation with the report 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, execution_id="abc-123" + ) + + assert result is None + call_args = mock_logger.exception.call_args + assert "abc-123" in call_args[0][2] def test_screenshot_clip_parameters(self, mock_page): """Test that screenshot clipping parameters are correct.""" @@ -353,7 +370,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: @@ -371,14 +388,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 execution_id 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_execution_id(self, mock_page): + """The execution id is threaded through for log correlation with the + report 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, + execution_id="abc-123", + ) + + warning_args = mock_logger.warning.call_args[0] + assert "abc-123" in warning_args[6] def test_chart_holder_with_nothing_mounted_blocks_wait(self, mock_page): """Regression test for the vacuous-pass race (PR #39895). @@ -402,7 +456,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"): @@ -414,6 +468,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, + 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 "abc-123" in first_call_args[5] + 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"): diff --git a/tests/unit_tests/utils/webdriver_test.py b/tests/unit_tests/utils/webdriver_test.py index 02b9ffe5d4a..64e1b42c8e1 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -1121,6 +1121,7 @@ class TestWebDriverPlaywrightAnimationWaitOrder: 600, load_wait=30, animation_wait=2, + execution_id=None, ) # The only wait_for_timeout call should be the 0ms headstart; no global # animation wait should be issued (handled per-tile by take_tiled_screenshot)