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): fail-loud WARNING diagnostics and log-context tracing for tile readiness

Browse Source 
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=<uuid>") 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 <noreply@anthropic.com>
This commit is contained in:
Elizabeth Thompson
2026-07-21 18:37:47 +00:00
parent a9ff21b573
commit 976e0d9d3e
6 changed files with 247 additions and 43 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

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

115
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,
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

9
superset/utils/screenshots.py
View File

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

26
superset/utils/webdriver.py
View File

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

4
tests/integration_tests/reports/commands_tests.py
View File

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

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

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