QT/superset2
1
0
Fork 0
mirror of https://github.com/apache/superset.git synced 2026-07-26 00:22:31 +00:00
Code Issues Packages Projects Releases Wiki Activity

fix(reports): warn (not error) on chart readiness timeout, add execution id and diagnostics

Browse Source 
The per-tile readiness timeout added in the prior commit logged at ERROR.
A chart failing to load in time is a customer chart-loading issue (slow
query, error state), not a Superset system fault, so downgrade it to
WARNING -- matching the precedent set in #38130 and #38441 for the other
screenshot timeout paths. The report still fails loudly (raise is
unchanged); only the log level changes. Genuine system faults (the
catch-all Exception handler) stay at ERROR/exception level.

Thread an optional execution_id through
ChartScreenshot/DashboardScreenshot.get_screenshot -> WebDriverProxy
subclasses -> take_tiled_screenshot, populated from
BaseReportState._execution_id in the report pipeline (None elsewhere,
e.g. thumbnails), so every log line this change touches can be
correlated back to the report execution that produced it.

The readiness-timeout diagnostics now identify not just which chart
holders are unready but the state each is stuck in --
"waiting_on_database" (initial query in flight, whole container
replaced by a spinner), "spinner_mounted" (query finished but the
chart isn't in the virtualization viewport yet, spinner nested inside
an otherwise-present slice_container), or "nothing_mounted" (the
vacuous-pass race the previous commit closed) -- so a slow query can be
told apart from the virtualization race during an incident. Also added
a per-tile DEBUG line with the time spent waiting for readiness, to
profile slow dashboards from logs.

Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
Elizabeth Thompson
2026-07-16 22:38:39 +00:00
parent d32c2b891f
commit 37da786b52
6 changed files with 218 additions and 37 deletions
Download Patch File Download Diff File Expand all files Collapse all files

4
superset/commands/report/execute.py
View File

@@ -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"

94
superset/utils/screenshot_utils.py
View File

@@ -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

9
superset/utils/screenshots.py
View File

@@ -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()

22
superset/utils/webdriver.py
View File

@@ -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

125
tests/unit_tests/utils/test_screenshot_utils.py
View File

@@ -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"):

1
tests/unit_tests/utils/webdriver_test.py
View File

@@ -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)