fix(reports): align correlation-id plumbing with fix-tile-wait-budget's log_context

Renamed the execution_id parameter/suffix mechanism added in the previous
commit to log_context / " [context]", matching the mechanism used by the
concurrent fix-tile-wait-budget PR (#42118) for the same call chain
(BaseReportState._get_screenshots -> BaseScreenshot.get_screenshot ->
WebDriverProxy subclasses -> take_tiled_screenshot). Both PRs touch
take_tiled_screenshot()'s signature, so using the same parameter name and
suffix format keeps the eventual rebase mechanical instead of producing a
semantic conflict and two different correlation-id formats in the logs.

The call site in execute.py now passes log_context=f"execution_id=..."
(rather than a bare execution_id kwarg), matching #42118's convention of
a self-describing context string (it uses cache_key=... for thumbnails).

Only the correlation-id plumbing changed -- the per-chart unready-state
diagnostics (chart id + waiting_on_database/spinner_mounted/nothing_mounted)
added in the previous commit are unchanged.

Co-Authored-By: Claude <noreply@anthropic.com>

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, log_context=f"execution_id={self._execution_id}"
+                )
                 if imge is None:
                     raise ReportScheduleScreenshotFailedError(
                         "Screenshot failed; aborting to avoid sending a partial report"

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
@@ -39,6 +40,80 @@ if TYPE_CHECKING:
     except ImportError:
         Page = None
 
+# Selectors used to build a positive per-tile readiness check. A chart holder
+# is only "ready" once it shows a terminal state (a rendered chart or an
+# error/empty state) -- the mere absence of a `.loading` element is not
+# sufficient, since a chart holder that intersects the viewport but hasn't
+# mounted anything yet (e.g. its IntersectionObserver callback hasn't fired)
+# would otherwise pass vacuously.
+# 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, `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"]'
+    );
+    const unready = [];
+    for (const holder of holders) {
+        const r = holder.getBoundingClientRect();
+        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 = hasSliceContainer || holder.querySelector(
+            '[role="alert"], .ant-empty, .missing-chart-container'
+        ) !== null;
+        if (stillLoading || !isReady) {
+            const chartIdEl = holder.querySelector('[data-test-chart-id]');
+            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,
+            });
+        }
+    }
+"""
+
+# Predicate for page.wait_for_function: true once every viewport-visible chart
+# holder has reached a terminal state.
+_TILE_READY_CHECK_JS = (
+    f"() => {{ {_UNREADY_CHART_HOLDERS_JS_BODY} return unready.length === 0; }}"
+)
+
+# 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; }}"
+)
+
 
 def combine_screenshot_tiles(screenshot_tiles: list[bytes]) -> bytes:
     """
@@ -90,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.
@@ -100,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)
+        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 ""
     try:
         # Get the target element
         element = page.locator(f".{element_name}")
@@ -150,30 +230,49 @@ def take_tiled_screenshot(
             )
             # Wait for scroll to settle and content to load
             page.wait_for_timeout(SCROLL_SETTLE_TIMEOUT_MS)
-            # Wait for any loading spinners visible in the current viewport to clear.
-            # Only check viewport-visible spinners to avoid blocking on
-            # virtualization placeholders rendered for off-screen charts.
+            # Wait for every chart holder visible in the current viewport to reach
+            # a terminal state (rendered chart or error/empty state). Only check
+            # viewport-visible chart holders to avoid blocking on virtualization
+            # 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(
-                    """() => {
-                        const els = document.querySelectorAll('.loading');
-                        for (const el of els) {
-                            const r = el.getBoundingClientRect();
-                            if (r.top < window.innerHeight && r.bottom > 0) {
-                                return false;
-                            }
-                        }
-                        return true;
-                    }""",
+                    _TILE_READY_CHECK_JS,
                     timeout=load_wait * 1000,
                 )
             except PlaywrightTimeout:
+                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 waiting for visible spinners to clear on tile %s/%s "
-                    "(load_wait=%ss)",
+                    "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,
+                    context_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,
+                    context_suffix,
                 )
 
             # Wait for chart animations (e.g. ECharts) to finish after spinner clears.
@@ -229,6 +328,13 @@ 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("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, context_suffix)
         return None

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,
+        log_context: 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, log_context=log_context
+            )
         finally:
             if isinstance(driver, WebDriverSelenium):
                 driver.destroy()

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,
+        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.
         """
 
 
@@ -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,
+        log_context: 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,
+                            log_context=log_context,
                         )
                         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,
+        log_context: str | None = None,
     ) -> bytes | None:
         # If a user is passed explicitly and differs from the stored user,
         # update and re-authenticate

tests/unit_tests/utils/test_screenshot_utils.py

@@ -199,8 +199,29 @@ 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 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."""
@@ -321,8 +342,8 @@ class TestTakeTiledScreenshot:
             for call in mock_page.wait_for_timeout.call_args_list:
                 assert call[0][0] == SCROLL_SETTLE_TIMEOUT_MS
 
-    def test_per_tile_spinner_wait_uses_viewport_check(self, mock_page):
-        """wait_for_function polls viewport-visible spinners after each scroll."""
+    def test_per_tile_readiness_wait_uses_viewport_check(self, mock_page):
+        """wait_for_function polls viewport-visible chart holders after each scroll."""
         with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"):
             take_tiled_screenshot(
                 mock_page, "dashboard", tile_height=2000, load_wait=30
@@ -336,33 +357,183 @@ class TestTakeTiledScreenshot:
             js = call[0][0]
             assert "getBoundingClientRect" in js
             assert "window.innerHeight" in js
+            assert "dashboard-component-chart-holder" in js
             assert call[1]["timeout"] == 30 * 1000
 
-    def test_per_tile_spinner_timeout_logs_warning_and_continues(self, mock_page):
-        """A per-tile spinner timeout logs a warning but still takes the screenshot."""
+    def test_per_tile_readiness_timeout_raises_and_skips_capture(self, mock_page):
+        """A per-tile readiness timeout raises and does not capture that tile.
+
+        This is a product decision (fail loudly, never snapshot spinners or
+        blank charts): a per-tile timeout must abort the tiled screenshot
+        instead of warning and continuing.
+        """
         from superset.utils.screenshot_utils import PlaywrightTimeout
 
-        timeout = PlaywrightTimeout()
+        timeout = PlaywrightTimeout("Timeout waiting for chart holders")
         mock_page.wait_for_function.side_effect = timeout
+        mock_page.evaluate.side_effect = [
+            {"height": 5000, "top": 100, "left": 50, "width": 800},  # dimensions
+            None,  # window.scrollTo(...) for tile 1
+            [{"chartId": "42", "state": "waiting_on_database"}],  # diagnostics
+        ]
 
         with patch("superset.utils.screenshot_utils.logger") as mock_logger:
             with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"):
-                result = take_tiled_screenshot(
-                    mock_page, "dashboard", tile_height=2000, load_wait=30
+                with pytest.raises(PlaywrightTimeout):
+                    take_tiled_screenshot(
+                        mock_page, "dashboard", tile_height=2000, load_wait=30
+                    )
+
+        # No tile should have been captured -- fail loudly, don't snapshot
+        # a blank or partially-loaded tile.
+        mock_page.screenshot.assert_not_called()
+
+        # Only the first tile's wait_for_function is attempted (the timeout
+        # aborts before any subsequent tile is processed).
+        assert mock_page.wait_for_function.call_count == 1
+
+        # 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).
+
+        A chart holder that intersects the viewport but has not yet mounted
+        a spinner or a chart (e.g. its IntersectionObserver callback hasn't
+        fired) must not satisfy the readiness predicate.
+        """
+        from superset.utils.screenshot_utils import PlaywrightTimeout
+
+        js_call_count = {"n": 0}
+
+        def fake_wait_for_function(js, timeout=None):
+            js_call_count["n"] += 1
+            # Simulate evaluating the predicate against a DOM with a chart
+            # holder in viewport that has mounted nothing at all.
+            assert "dashboard-component-chart-holder" in js
+            raise PlaywrightTimeout("Timeout waiting for chart holders")
+
+        mock_page.wait_for_function.side_effect = fake_wait_for_function
+        mock_page.evaluate.side_effect = [
+            {"height": 2000, "top": 0, "left": 0, "width": 800},  # dimensions
+            None,  # window.scrollTo(...) for tile 1
+            [{"chartId": "7", "state": "nothing_mounted"}],  # diagnostics
+        ]
+
+        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
                 )
 
-        # Screenshot should still proceed (non-fatal)
-        assert result is not None
-        # Warning logged for each tile that timed out
-        assert mock_logger.warning.call_count == 3
-        mock_logger.warning.assert_any_call(
-            "Timed out waiting for visible spinners to clear on tile %s/%s "
-            "(load_wait=%ss)",
-            1,
-            3,
-            30,
+        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"):
+            result = take_tiled_screenshot(
+                mock_page, "dashboard", tile_height=2000, load_wait=5
+            )
+
+        # mock_page.wait_for_function is a MagicMock by default and does not
+        # raise, i.e. the readiness check passes immediately for every tile.
+        assert mock_page.wait_for_function.call_count == 3
+        assert mock_page.screenshot.call_count == 3
+        assert result is not None
+
     def test_load_wait_default_is_sixty_seconds(self):
         """load_wait defaults to 60 to match SCREENSHOT_LOAD_WAIT config default."""
         import inspect

tests/unit_tests/utils/webdriver_test.py

@@ -1121,6 +1121,7 @@ class TestWebDriverPlaywrightAnimationWaitOrder:
             600,
             load_wait=30,
             animation_wait=2,
+            log_context=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)