From 55e5d18b9fa369004ad2058bd1d8398b66c24306 Mon Sep 17 00:00:00 2001 From: Mafi Date: Thu, 30 Jul 2026 23:00:10 +0000 Subject: [PATCH 01/19] fix(reports): enforce readiness recovery budget --- .../configuration/alerts-reports.mdx | 22 +- superset/commands/report/execute.py | 339 ++++++++++- superset/commands/report/execute_now.py | 21 +- superset/config.py | 23 + .../screenshot/pooled_screenshot.py | 3 + superset/tasks/scheduler.py | 72 ++- superset/utils/report_execution.py | 168 ++++++ superset/utils/screenshot_utils.py | 240 +++++++- superset/utils/screenshots.py | 8 +- superset/utils/webdriver.py | 559 +++++++++++++++--- .../reports/scheduler_tests.py | 44 ++ .../commands/report/execute_test.py | 223 +++++++ .../commands/report/test_execute_now.py | 42 +- .../unit_tests/utils/test_report_execution.py | 106 ++++ .../unit_tests/utils/test_screenshot_utils.py | 120 +++- tests/unit_tests/utils/webdriver_test.py | 191 ++++-- 16 files changed, 1941 insertions(+), 240 deletions(-) create mode 100644 superset/utils/report_execution.py create mode 100644 tests/unit_tests/utils/test_report_execution.py diff --git a/docs/admin_docs/configuration/alerts-reports.mdx b/docs/admin_docs/configuration/alerts-reports.mdx index bedc88ac4c9a..462853bb5a51 100644 --- a/docs/admin_docs/configuration/alerts-reports.mdx +++ b/docs/admin_docs/configuration/alerts-reports.mdx @@ -244,8 +244,26 @@ class CeleryConfig: } CELERY_CONFIG = CeleryConfig -SCREENSHOT_LOCATE_WAIT = 100 -SCREENSHOT_LOAD_WAIT = 600 +# Scheduled reports share one 15-minute deadline across browser readiness, +# capture/PDF generation, delivery, and terminal-state persistence. Increase +# this only when the complete report pipeline is expected to take longer. +ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = 900 + +# These reserves are part of (not additions to) the total budget. Readiness +# polling stops in time to leave capacity for the later phases. +ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS = 60 +ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS = 120 +ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS = 30 + +# Celery's hard limit leaves this additional window for terminal cleanup after +# the 15-minute soft limit. +ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS = 30 + +# Screenshot-specific waits continue to apply to thumbnails and other +# standalone screenshot calls. Scheduled reports derive their waits from the +# shared execution deadline above. +SCREENSHOT_LOCATE_WAIT = 10 +SCREENSHOT_LOAD_WAIT = 60 # Slack configuration SLACK_API_TOKEN = "xoxb-" diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index e6e9bea0e5cb..45942f21d5ea 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -15,6 +15,7 @@ # specific language governing permissions and limitations # under the License. import logging +import time import urllib.parse import urllib.request from collections.abc import Sequence @@ -89,6 +90,10 @@ from superset.utils.decorators import logs_context, transaction from superset.utils.file import sanitize_title from superset.utils.pdf import build_pdf_from_screenshots +from superset.utils.report_execution import ( + ReportExecutionContext, + ReportExecutionDeadline, +) from superset.utils.screenshots import ChartScreenshot, DashboardScreenshot from superset.utils.slack import get_channels_with_search, SlackChannelTypes from superset.utils.urls import get_url_path @@ -123,6 +128,70 @@ def resolve_executor_user(model: ReportSchedule) -> tuple["User", str]: return user, username +def mark_report_execution_terminal_error( + report_schedule_id: int, + execution_id: UUID, + terminal_reason: str, +) -> bool: + """Idempotently terminate the WORKING row owned by a failed Celery task.""" + + try: + working_log = ( + db.session.query(ReportExecutionLog) + .filter( + ReportExecutionLog.report_schedule_id == report_schedule_id, + ReportExecutionLog.uuid == execution_id, + ReportExecutionLog.state == ReportState.WORKING, + ReportExecutionLog.error_message.is_(None), + ) + .first() + ) + if working_log is None: + return False + + latest_working_log = ( + db.session.query(ReportExecutionLog) + .filter( + ReportExecutionLog.report_schedule_id == report_schedule_id, + ReportExecutionLog.state == ReportState.WORKING, + ReportExecutionLog.error_message.is_(None), + ) + .order_by(ReportExecutionLog.end_dttm.desc()) + .first() + ) + report_schedule = working_log.report_schedule + owns_schedule_state = ( + report_schedule.last_state == ReportState.WORKING + and latest_working_log is not None + and latest_working_log.uuid == execution_id + ) + ended_at = datetime.now(timezone.utc).replace(tzinfo=None) + working_log.state = ReportState.ERROR + working_log.error_message = terminal_reason + working_log.end_dttm = ended_at + if owns_schedule_state: + report_schedule.last_state = ReportState.ERROR + report_schedule.last_eval_dttm = ended_at + + db.session.commit() # pylint: disable=consider-using-transaction + logger.warning( + "report_execution_terminal capture_kind=report execution_id=%s " + "report_schedule_id=%s " + "dashboard_id=%s chart_id=%s state=%s terminal_reason=%s " + "elapsed_seconds=unknown remaining_seconds=unknown", + execution_id, + report_schedule_id, + report_schedule.dashboard_id, + report_schedule.chart_id, + ReportState.ERROR.value, + terminal_reason, + ) + return True + except Exception: + db.session.rollback() # pylint: disable=consider-using-transaction + raise + + class BaseReportState: current_states: list[ReportState] = [] initial: bool = False @@ -133,13 +202,42 @@ def __init__( report_schedule: ReportSchedule, scheduled_dttm: datetime, execution_id: UUID, + report_execution_context: ReportExecutionContext | None = None, ) -> None: self._report_schedule = report_schedule self._scheduled_dttm = scheduled_dttm self._start_dttm: datetime = datetime.now(timezone.utc).replace(tzinfo=None) self._execution_id = execution_id + self._report_execution_context = report_execution_context self._filter_warnings: list[str] = [] + @property + def _log_context(self) -> str: + if self._report_execution_context: + return self._report_execution_context.log_context + return f"execution_id={self._execution_id}" + + def _budget_values(self) -> tuple[float | None, float | None]: + if not self._report_execution_context: + return None, None + deadline = self._report_execution_context.deadline + return deadline.elapsed_seconds, deadline.remaining_seconds + + def _phase_timeout( + self, + phase: str, + *, + requested_seconds: float | None = None, + reserve_seconds: float = 0.0, + ) -> float | None: + if not self._report_execution_context: + return requested_seconds + return self._report_execution_context.deadline.timeout_seconds( + phase, + requested_seconds=requested_seconds, + reserve_seconds=reserve_seconds, + ) + def update_report_schedule_and_log( self, state: ReportState, @@ -151,6 +249,17 @@ def update_report_schedule_and_log( """ self.update_report_schedule(state) self.create_log(error_message) + if state != ReportState.WORKING: + elapsed, remaining = self._budget_values() + logger.info( + "report_execution_terminal %s state=%s terminal_reason=%s " + "elapsed_seconds=%s remaining_seconds=%s", + self._log_context, + state.value, + error_message or state.value, + f"{elapsed:.2f}" if elapsed is not None else None, + f"{remaining:.2f}" if remaining is not None else None, + ) def update_report_schedule(self, state: ReportState) -> None: """ @@ -592,7 +701,9 @@ def _get_screenshots(self) -> list[bytes]: imges = [] for screenshot in screenshots: imge = screenshot.get_screenshot( - user=user, log_context=f"execution_id={self._execution_id}" + user=user, + log_context=self._log_context, + report_execution_context=self._report_execution_context, ) if imge is None: raise ReportScheduleScreenshotFailedError( @@ -603,18 +714,31 @@ def _get_screenshots(self) -> list[bytes]: datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() logger.info( - "Screenshot capture took %.2fs - execution_id: %s", + "report_capture_complete %s elapsed_seconds=%.2f " + "remaining_seconds=%s screenshot_count=%s", + self._log_context, elapsed_seconds, - self._execution_id, + ( + f"{self._report_execution_context.deadline.remaining_seconds:.2f}" + if self._report_execution_context + else None + ), + len(imges), ) except SoftTimeLimitExceeded as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() logger.warning( - "Screenshot timeout after %.2fs - execution_id: %s", + "report_capture_terminal %s elapsed_seconds=%.2f " + "remaining_seconds=%s terminal_reason=celery_soft_timeout", + self._log_context, elapsed_seconds, - self._execution_id, + ( + f"{self._report_execution_context.deadline.remaining_seconds:.2f}" + if self._report_execution_context + else None + ), ) raise ReportScheduleScreenshotTimeout() from ex except Exception as ex: @@ -622,9 +746,16 @@ def _get_screenshots(self) -> list[bytes]: datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() logger.error( - "Screenshot failed after %.2fs - execution_id: %s", + "report_capture_terminal %s elapsed_seconds=%.2f " + "remaining_seconds=%s terminal_reason=%s", + self._log_context, elapsed_seconds, - self._execution_id, + ( + f"{self._report_execution_context.deadline.remaining_seconds:.2f}" + if self._report_execution_context + else None + ), + type(ex).__name__, ) raise ReportScheduleScreenshotFailedError( f"Failed taking a screenshot {str(ex)}" @@ -639,7 +770,20 @@ def _get_pdf(self) -> bytes: :raises: ReportSchedulePdfFailedError """ screenshots = self._get_screenshots() + reserve_seconds = ( + self._report_execution_context.post_capture_reserve_seconds + if self._report_execution_context + else 0.0 + ) + self._phase_timeout( + "pdf_generation", + reserve_seconds=reserve_seconds, + ) pdf = build_pdf_from_screenshots(screenshots) + self._phase_timeout( + "pdf_generation", + reserve_seconds=reserve_seconds, + ) return pdf @@ -789,7 +933,17 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: data = get_chart_csv_data( chart_url=url, auth_cookies=auth_cookies, - timeout=app.config["ALERT_REPORTS_CSV_REQUEST_TIMEOUT"], + timeout=self._phase_timeout( + "data_generation", + requested_seconds=app.config[ + "ALERT_REPORTS_CSV_REQUEST_TIMEOUT" + ], + reserve_seconds=( + self._report_execution_context.post_capture_reserve_seconds + if self._report_execution_context + else 0.0 + ), + ), ) else: request_payload = self._get_chart_data_request_payload(result_format) @@ -798,7 +952,17 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: chart_url=url, auth_cookies=auth_cookies, request_payload=request_payload, - timeout=app.config["ALERT_REPORTS_CSV_REQUEST_TIMEOUT"], + timeout=self._phase_timeout( + "data_generation", + requested_seconds=app.config[ + "ALERT_REPORTS_CSV_REQUEST_TIMEOUT" + ], + reserve_seconds=( + self._report_execution_context.post_capture_reserve_seconds + if self._report_execution_context + else 0.0 + ), + ), ) elapsed_seconds: float = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time @@ -855,7 +1019,15 @@ def _get_embedded_data(self) -> pd.DataFrame: dataframe = get_chart_dataframe( url, auth_cookies, - timeout=app.config["ALERT_REPORTS_CSV_REQUEST_TIMEOUT"], + timeout=self._phase_timeout( + "dataframe_generation", + requested_seconds=app.config["ALERT_REPORTS_CSV_REQUEST_TIMEOUT"], + reserve_seconds=( + self._report_execution_context.post_capture_reserve_seconds + if self._report_execution_context + else 0.0 + ), + ), ) elapsed_seconds: float = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time @@ -1052,6 +1224,24 @@ def _send( notification = create_notification(recipient, notification_content) try: try: + cleanup_reserve = ( + self._report_execution_context.cleanup_reserve_seconds + if self._report_execution_context + else 0.0 + ) + self._phase_timeout( + "notification_delivery", + reserve_seconds=cleanup_reserve, + ) + elapsed, remaining = self._budget_values() + logger.info( + "report_delivery_start %s recipient_type=%s " + "elapsed_seconds=%s remaining_seconds=%s", + self._log_context, + recipient.type, + f"{elapsed:.2f}" if elapsed is not None else None, + f"{remaining:.2f}" if remaining is not None else None, + ) if app.config["ALERT_REPORTS_NOTIFICATION_DRY_RUN"]: logger.info( "Would send notification for alert %s, to %s. " @@ -1062,6 +1252,15 @@ def _send( ) else: notification.send() + elapsed, remaining = self._budget_values() + logger.info( + "report_delivery_complete %s recipient_type=%s " + "elapsed_seconds=%s remaining_seconds=%s", + self._log_context, + recipient.type, + f"{elapsed:.2f}" if elapsed is not None else None, + f"{remaining:.2f}" if remaining is not None else None, + ) except SlackV1NotificationError as ex: # The slack notification should be sent with the v2 api logger.info( @@ -1070,6 +1269,14 @@ def _send( self.update_report_schedule_slack_v2() recipient.type = ReportRecipientType.SLACKV2 notification = create_notification(recipient, notification_content) + self._phase_timeout( + "notification_delivery", + reserve_seconds=( + self._report_execution_context.cleanup_reserve_seconds + if self._report_execution_context + else 0.0 + ), + ) notification.send() except ( UpdateFailedError, @@ -1174,11 +1381,19 @@ def is_on_working_timeout(self) -> bool: ) if not last_working: return False + working_timeout = self._report_schedule.working_timeout + if self._report_schedule.type == ReportScheduleType.REPORT: + execution_budget = app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] + working_timeout = ( + min(working_timeout, execution_budget) + if working_timeout is not None + else execution_budget + ) return ( - self._report_schedule.working_timeout is not None + working_timeout is not None and self._report_schedule.last_eval_dttm is not None and datetime.now(timezone.utc).replace(tzinfo=None) - - timedelta(seconds=self._report_schedule.working_timeout) + - timedelta(seconds=working_timeout) > last_working.end_dttm ) @@ -1219,6 +1434,15 @@ def next(self) -> None: # noqa: C901 self.update_report_schedule_and_log( ReportState.SUCCESS, error_message=warning_message ) + except SoftTimeLimitExceeded: + # Persist the terminal state inside the cleanup grace period rather + # than spending it on an error notification. The task-level handler + # is a second, idempotent safety net for failures outside this state. + self.update_report_schedule_and_log( + ReportState.ERROR, + error_message="celery_soft_timeout", + ) + raise except (SupersetErrorsException, Exception) as first_ex: error_message = str(first_ex) if isinstance(first_ex, SupersetErrorsException): @@ -1306,10 +1530,36 @@ def next(self) -> None: self._execution_id, ) exception_timeout = ReportScheduleWorkingTimeoutError() - self.update_report_schedule_and_log( - ReportState.ERROR, - error_message=str(exception_timeout), - ) + stale_execution_id = last_working.uuid if last_working else None + if stale_execution_id is not None: + mark_report_execution_terminal_error( + self._report_schedule.id, + stale_execution_id, + "working_timeout_recovery", + ) + if ( + self._report_schedule.type == ReportScheduleType.REPORT + and stale_execution_id != self._execution_id + ): + logger.info( + "report_execution_recovered %s stale_execution_id=%s " + "terminal_reason=working_timeout_recovery; " + "proceeding with new scheduled execution", + self._log_context, + stale_execution_id, + ) + ReportNotTriggeredErrorState( + self._report_schedule, + self._scheduled_dttm, + self._execution_id, + self._report_execution_context, + ).next() + return + if stale_execution_id != self._execution_id: + self.update_report_schedule_and_log( + ReportState.ERROR, + error_message=str(exception_timeout), + ) raise exception_timeout logger.warning( "Report still in working state, refusing to re-compute - execution_id: %s", @@ -1437,10 +1687,12 @@ def __init__( task_uuid: UUID, report_schedule: ReportSchedule, scheduled_dttm: datetime, + report_execution_context: ReportExecutionContext | None = None, ): self._execution_id = task_uuid self._report_schedule = report_schedule self._scheduled_dttm = scheduled_dttm + self._report_execution_context = report_execution_context @transaction() def run(self) -> None: @@ -1452,6 +1704,7 @@ def run(self) -> None: self._report_schedule, self._scheduled_dttm, self._execution_id, + self._report_execution_context, ).next() break else: @@ -1472,11 +1725,53 @@ def __init__(self, task_id: str, model_id: int, scheduled_dttm: datetime): self._execution_id = UUID(task_id) def run(self) -> None: + monotonic_started_at = time.monotonic() try: self.validate() if not self._model: raise ReportScheduleExecuteUnexpectedError() + report_execution_context = None + if self._model.type == ReportScheduleType.REPORT: + total_seconds = float( + app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] + ) + deadline = ReportExecutionDeadline( + total_seconds=total_seconds, + started_at=monotonic_started_at, + ) + dashboard = self._model.dashboard + expected_chart_count = ( + len(dashboard.slices) + if dashboard is not None and dashboard.slices is not None + else (1 if self._model.chart_id is not None else None) + ) + report_execution_context = ReportExecutionContext( + execution_id=self._execution_id, + report_schedule_id=self._model.id, + dashboard_id=self._model.dashboard_id, + chart_id=self._model.chart_id, + expected_chart_count=expected_chart_count, + deadline=deadline, + capture_reserve_seconds=float( + app.config["ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS"] + ), + delivery_reserve_seconds=float( + app.config["ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS"] + ), + cleanup_reserve_seconds=float( + app.config["ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS"] + ), + ) + logger.info( + "report_execution_start %s total_budget_seconds=%.2f " + "elapsed_seconds=%.2f remaining_seconds=%.2f", + report_execution_context.log_context, + deadline.total_seconds, + deadline.elapsed_seconds, + deadline.remaining_seconds, + ) + # Resolve the executor at the run() boundary, tolerating a missing # user (find_user -> None) so the state machine still runs and its # error envelope writes the ERROR execution-log row and sends the @@ -1507,10 +1802,16 @@ def run(self) -> None: # already-committed row without a second INSERT. if self._model.dashboard_id: BaseReportState( - self._model, self._scheduled_dttm, self._execution_id + self._model, + self._scheduled_dttm, + self._execution_id, + report_execution_context, ).get_dashboard_urls() ReportScheduleStateMachine( - self._execution_id, self._model, self._scheduled_dttm + self._execution_id, + self._model, + self._scheduled_dttm, + report_execution_context, ).run() elapsed_seconds: float = ( @@ -1522,7 +1823,7 @@ def run(self) -> None: elapsed_seconds, self._execution_id, ) - except CommandException: + except (CommandException, SoftTimeLimitExceeded): raise except Exception as ex: raise ReportScheduleUnexpectedError(str(ex)) from ex diff --git a/superset/commands/report/execute_now.py b/superset/commands/report/execute_now.py index ee61ae74ee63..cea73f4770f0 100644 --- a/superset/commands/report/execute_now.py +++ b/superset/commands/report/execute_now.py @@ -33,7 +33,8 @@ ) from superset.daos.report import ReportScheduleDAO from superset.exceptions import SupersetSecurityException -from superset.reports.models import ReportSchedule +from superset.reports.models import ReportSchedule, ReportScheduleType +from superset.utils.report_execution import get_report_task_timeout_options logger = logging.getLogger(__name__) @@ -88,19 +89,13 @@ def run(self) -> str: "eta": datetime.now(tz=timezone.utc), } - if self._model.working_timeout is not None and current_app.config.get( - "ALERT_REPORTS_WORKING_TIME_OUT_KILL", True - ): - async_options["time_limit"] = ( - self._model.working_timeout - + current_app.config.get("ALERT_REPORTS_WORKING_TIME_OUT_LAG", 10) - ) - async_options["soft_time_limit"] = ( - self._model.working_timeout - + current_app.config.get( - "ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG", 5 - ) + async_options.update( + get_report_task_timeout_options( + is_report=self._model.type == ReportScheduleType.REPORT, + working_timeout=self._model.working_timeout, + config=current_app.config, ) + ) try: execute.apply_async((self._model.id,), **async_options) diff --git a/superset/config.py b/superset/config.py index 82f14935754f..2d0808bbcb1a 100644 --- a/superset/config.py +++ b/superset/config.py @@ -2443,6 +2443,29 @@ def EMAIL_HEADER_MUTATOR( # pylint: disable=invalid-name,unused-argument # noq ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG = int(timedelta(seconds=1).total_seconds()) # Default values that user using when creating alert ALERT_REPORTS_DEFAULT_WORKING_TIMEOUT = 3600 +# End-to-end wall-clock budget for a scheduled report execution. A single +# monotonic deadline derived from this value is shared by browser setup, +# readiness, capture/PDF generation, and notification delivery. Alerts retain +# their per-schedule ``working_timeout`` behavior because query evaluation and +# grace handling have different runtime characteristics. +ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = int(timedelta(minutes=15).total_seconds()) +# Capacity inside the execution budget reserved from chart-readiness polling +# for image capture/PDF construction, notification delivery, and the terminal +# execution-log transition, respectively. Unused capacity flows to later phases. +ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS = int( + timedelta(minutes=1).total_seconds() +) +ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS = int( + timedelta(minutes=2).total_seconds() +) +ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS = int( + timedelta(seconds=30).total_seconds() +) +# Celery raises the soft timeout at the execution deadline. The hard timeout +# leaves this additional window for the soft-timeout handler to persist ERROR. +ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS = int( + timedelta(seconds=30).total_seconds() +) ALERT_REPORTS_DEFAULT_RETENTION = 90 ALERT_REPORTS_DEFAULT_CRON_VALUE = "0 0 * * *" # every day # If set to true no notification is sent, the worker will just log a message. diff --git a/superset/mcp_service/screenshot/pooled_screenshot.py b/superset/mcp_service/screenshot/pooled_screenshot.py index 977d4899b9f4..136806b42934 100644 --- a/superset/mcp_service/screenshot/pooled_screenshot.py +++ b/superset/mcp_service/screenshot/pooled_screenshot.py @@ -33,6 +33,7 @@ from superset.extensions import machine_auth_provider_factory from superset.mcp_service.screenshot.webdriver_pool import get_webdriver_pool from superset.mcp_service.utils.retry_utils import retry_screenshot_operation +from superset.utils.report_execution import ReportExecutionContext from superset.utils.screenshots import BaseScreenshot, WindowSize logger = logging.getLogger(__name__) @@ -54,6 +55,7 @@ def get_screenshot( user: User, window_size: WindowSize | None = None, log_context: str | None = None, + report_execution_context: ReportExecutionContext | None = None, ) -> bytes | None: """ Generate screenshot using pooled WebDriver with retry logic for reliability. @@ -64,6 +66,7 @@ def get_screenshot( log_context: Accepted for signature compatibility with BaseScreenshot; the pooled Selenium path does not emit the per-tile readiness logs that use it. + report_execution_context: Accepted for BaseScreenshot compatibility. Returns: Screenshot as PNG bytes or None if failed diff --git a/superset/tasks/scheduler.py b/superset/tasks/scheduler.py index a37c049a06ac..7d1147dbdfc9 100644 --- a/superset/tasks/scheduler.py +++ b/superset/tasks/scheduler.py @@ -31,7 +31,10 @@ from superset.commands.exceptions import CommandException from superset.commands.logs.prune import LogPruneCommand from superset.commands.report.exceptions import ReportScheduleUnexpectedError -from superset.commands.report.execute import AsyncExecuteReportScheduleCommand +from superset.commands.report.execute import ( + AsyncExecuteReportScheduleCommand, + mark_report_execution_terminal_error, +) from superset.commands.report.log_prune import AsyncPruneReportScheduleLogCommand from superset.commands.sql_lab.query import QueryPruneCommand from superset.commands.tasks.prune import TaskPruneCommand @@ -39,6 +42,7 @@ from superset.daos.tasks import TaskDAO from superset.extensions import celery_app from superset.key_value.commands.prune import KeyValuePruneCommand +from superset.reports.models import ReportScheduleType from superset.stats_logger import BaseStatsLogger from superset.tasks.ambient_context import use_context from superset.tasks.constants import ABORT_STATES, TERMINAL_STATES @@ -48,6 +52,7 @@ from superset.tasks.registry import TaskRegistry from superset.utils.core import LoggerLevel from superset.utils.log import get_logger_from_status +from superset.utils.report_execution import get_report_task_timeout_options logger = logging.getLogger(__name__) @@ -65,6 +70,27 @@ def log_task_failure( # pylint: disable=unused-argument ) -> None: task_name = sender.name if sender else "Unknown" logger.exception("Celery task %s failed: %s", task_name, exception, exc_info=einfo) + if task_name != "reports.execute" or task_id is None or not args: + return + try: + execution_id = UUID(task_id) + report_schedule_id = int(args[0]) + exception_name = type(exception).__name__ if exception else "UnknownError" + terminal_reason = f"celery_task_failure:{exception_name}" + mark_report_execution_terminal_error( + report_schedule_id, + execution_id, + terminal_reason, + ) + except Exception: + # Celery signal handlers must not mask the original task failure. + logger.exception( + "Failed terminal cleanup for report task capture_kind=report " + "execution_id=%s " + "report_schedule_id=%s terminal_reason=cleanup_hook_failed", + task_id, + args[0], + ) @celery_app.task( @@ -98,19 +124,14 @@ def scheduler(self: Task) -> None: # pylint: disable=unused-argument triggered_at, active_schedule.crontab, active_schedule.timezone ): logger.info("Scheduling alert %s eta: %s", active_schedule.name, schedule) - async_options = {"eta": schedule} - if ( - active_schedule.working_timeout is not None - and current_app.config["ALERT_REPORTS_WORKING_TIME_OUT_KILL"] - ): - async_options["time_limit"] = ( - active_schedule.working_timeout - + current_app.config["ALERT_REPORTS_WORKING_TIME_OUT_LAG"] - ) - async_options["soft_time_limit"] = ( - active_schedule.working_timeout - + current_app.config["ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG"] - ) + async_options = { + "eta": schedule, + **get_report_task_timeout_options( + is_report=active_schedule.type == ReportScheduleType.REPORT, + working_timeout=active_schedule.working_timeout, + config=current_app.config, + ), + } execute.apply_async((active_schedule.id,), **async_options) @@ -133,10 +154,33 @@ def execute(self: Task, report_schedule_id: int) -> None: report_schedule_id, scheduled_dttm, ).run() + except SoftTimeLimitExceeded: + logger.warning( + "Report execution hit Celery soft timeout; capture_kind=report " + "execution_id=%s " + "report_schedule_id=%s terminal_reason=celery_soft_timeout", + task_id, + report_schedule_id, + exc_info=True, + ) + if task_id: + mark_report_execution_terminal_error( + report_schedule_id, + UUID(task_id), + "celery_soft_timeout", + ) + self.update_state(state="FAILURE") + raise except ReportScheduleUnexpectedError: logger.exception( "An unexpected error occurred while executing the report: %s", task_id ) + if task_id: + mark_report_execution_terminal_error( + report_schedule_id, + UUID(task_id), + "unexpected_execution_error", + ) self.update_state(state="FAILURE") except CommandException as ex: logger_func, level = get_logger_from_status(ex.status) diff --git a/superset/utils/report_execution.py b/superset/utils/report_execution.py new file mode 100644 index 000000000000..c402829e6a5d --- /dev/null +++ b/superset/utils/report_execution.py @@ -0,0 +1,168 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Shared deadline and logging context for scheduled report execution.""" + +from __future__ import annotations + +import time +from collections.abc import Callable, Mapping +from dataclasses import dataclass, field +from typing import Any +from uuid import UUID + + +class ReportExecutionBudgetExceededError(TimeoutError): + """Raised before a report phase would overrun its execution deadline.""" + + def __init__( + self, + phase: str, + *, + elapsed_seconds: float, + remaining_seconds: float, + ) -> None: + self.phase = phase + self.elapsed_seconds = elapsed_seconds + self.remaining_seconds = remaining_seconds + super().__init__( + f"Report execution budget exhausted before {phase} " + f"(elapsed={elapsed_seconds:.2f}s, remaining={remaining_seconds:.2f}s)" + ) + + +@dataclass(frozen=True) +class ReportExecutionDeadline: + """A monotonic end-to-end deadline shared by every report phase.""" + + total_seconds: float + started_at: float = field(default_factory=time.monotonic) + _clock: Callable[[], float] = field( + default=time.monotonic, + repr=False, + compare=False, + ) + + @property + def elapsed_seconds(self) -> float: + """Return non-negative wall-clock time consumed by this execution.""" + + return max(0.0, self._clock() - self.started_at) + + @property + def remaining_seconds(self) -> float: + """Return wall-clock time left before the execution deadline.""" + + return max(0.0, self.total_seconds - self.elapsed_seconds) + + def available_seconds(self, phase: str, *, reserve_seconds: float = 0.0) -> float: + """Return time available to a phase after preserving later-phase capacity.""" + + available = self.remaining_seconds - max(0.0, reserve_seconds) + if available <= 0: + raise ReportExecutionBudgetExceededError( + phase, + elapsed_seconds=self.elapsed_seconds, + remaining_seconds=self.remaining_seconds, + ) + return available + + def timeout_seconds( + self, + phase: str, + *, + requested_seconds: float | None = None, + reserve_seconds: float = 0.0, + ) -> float: + """Cap an operation timeout at the time available to its report phase.""" + + available = self.available_seconds( + phase, + reserve_seconds=reserve_seconds, + ) + if requested_seconds is None or requested_seconds <= 0: + return available + return min(float(requested_seconds), available) + + +@dataclass(frozen=True) +class ReportExecutionContext: + """Identifiers, deadline, and phase reserves shared by one report attempt.""" + + execution_id: UUID + report_schedule_id: int + deadline: ReportExecutionDeadline + dashboard_id: int | None = None + chart_id: int | None = None + expected_chart_count: int | None = None + attempt: int = 1 + capture_reserve_seconds: float = 0.0 + delivery_reserve_seconds: float = 0.0 + cleanup_reserve_seconds: float = 0.0 + + @property + def log_context(self) -> str: + """Return stable key/value identifiers for plain-text log formatters.""" + + return ( + f"capture_kind=report execution_id={self.execution_id} " + f"report_schedule_id={self.report_schedule_id} " + f"dashboard_id={self.dashboard_id} chart_id={self.chart_id} " + f"expected_holders={self.expected_chart_count} attempt={self.attempt}" + ) + + @property + def readiness_reserve_seconds(self) -> float: + """Capacity kept for capture, delivery, and terminal state persistence.""" + + return ( + self.capture_reserve_seconds + + self.delivery_reserve_seconds + + self.cleanup_reserve_seconds + ) + + @property + def post_capture_reserve_seconds(self) -> float: + """Capacity kept for delivery and terminal state persistence.""" + + return self.delivery_reserve_seconds + self.cleanup_reserve_seconds + + +def get_report_task_timeout_options( + *, + is_report: bool, + working_timeout: int | None, + config: Mapping[str, Any], +) -> dict[str, int]: + """Return Celery time limits aligned with the application execution budget.""" + + if not config["ALERT_REPORTS_WORKING_TIME_OUT_KILL"]: + return {} + if is_report: + budget = int(config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"]) + hard_grace = int(config["ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS"]) + return { + "soft_time_limit": budget, + "time_limit": budget + hard_grace, + } + if working_timeout is None: + return {} + return { + "soft_time_limit": working_timeout + + int(config["ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG"]), + "time_limit": working_timeout + + int(config["ALERT_REPORTS_WORKING_TIME_OUT_LAG"]), + } diff --git a/superset/utils/screenshot_utils.py b/superset/utils/screenshot_utils.py index 868b8e731d55..2883d23d657a 100644 --- a/superset/utils/screenshot_utils.py +++ b/superset/utils/screenshot_utils.py @@ -25,6 +25,11 @@ from celery import current_task from PIL import Image +from superset.utils.report_execution import ( + ReportExecutionBudgetExceededError, + ReportExecutionContext, +) + logger = logging.getLogger(__name__) # Time to wait after scrolling for content to settle and load (in milliseconds) @@ -39,6 +44,10 @@ SCREENSHOT_TASK_BUDGET_MAX_MARGIN_SECONDS = 300 +class TiledScreenshotBudgetExceededError(TimeoutError): + """Raised when a tiled capture exhausts its shared screenshot budget.""" + + def resolve_screenshot_task_budget_seconds( log_context: str | None = None, ) -> float | None: @@ -189,7 +198,11 @@ def resolve_screenshot_task_budget_seconds( """ CHART_HOLDERS_READY_JS = ( - f"() => {{ {UNREADY_CHART_HOLDERS_JS_BODY} return unready.length === 0; }}" + f"() => {{ {UNREADY_CHART_HOLDERS_JS_BODY} " + "return holders.length > 0 && unready.length === 0; }" +) +CHART_HOLDERS_MOUNTED_JS = ( + f"() => document.querySelectorAll('{CHART_HOLDER_SELECTOR}').length > 0" ) FIND_UNREADY_CHART_HOLDERS_JS = ( f"() => {{ {UNREADY_CHART_HOLDERS_JS_BODY} return unready; }}" @@ -251,13 +264,15 @@ def combine_screenshot_tiles(screenshot_tiles: list[bytes]) -> bytes: return screenshot_tiles[0] -def take_tiled_screenshot( +def take_tiled_screenshot( # noqa: C901 page: "Page", element_name: str, tile_height: int, load_wait: int = 60, animation_wait: int = 0, log_context: str | None = None, + report_execution_context: ReportExecutionContext | None = None, + url: str | None = None, ) -> bytes | None: """ Take a tiled screenshot of a large dashboard by scrolling and capturing sections. @@ -271,10 +286,15 @@ def take_tiled_screenshot( 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. + report_execution_context: Shared report identifiers, phase reserves, + and end-to-end deadline. Thumbnail callers leave this unset. + url: Dashboard URL included in structured capture logs. Returns: Combined screenshot bytes or None if failed """ + if report_execution_context: + log_context = report_execution_context.log_context 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 @@ -286,10 +306,99 @@ def take_tiled_screenshot( # match `except PlaywrightTimeout` and incorrectly propagate instead of # degrading to `None` like every other unexpected error in this function. readiness_timeout = False + screenshot_started_at = time.monotonic() + task_budget = ( + None + if report_execution_context + else resolve_screenshot_task_budget_seconds(log_context) + ) + + def _deadline_values() -> tuple[float, float | None]: + if report_execution_context: + deadline = report_execution_context.deadline + return deadline.elapsed_seconds, deadline.remaining_seconds + elapsed = max(0.0, time.monotonic() - screenshot_started_at) + remaining = task_budget - elapsed if task_budget is not None else None + return elapsed, remaining + + def _timeout_seconds( + phase: str, + *, + requested_seconds: float | None = None, + reserve_seconds: float = 0.0, + ) -> float: + if report_execution_context: + return report_execution_context.deadline.timeout_seconds( + phase, + requested_seconds=requested_seconds, + reserve_seconds=reserve_seconds, + ) + elapsed, remaining = _deadline_values() + if remaining is not None and remaining <= 0: + raise TiledScreenshotBudgetExceededError( + f"Tiled screenshot budget of {task_budget:.2f}s exhausted " + f"before {phase} after {elapsed:.2f}s" + ) + if remaining is None: + return float(requested_seconds or load_wait) + if requested_seconds is None or requested_seconds <= 0: + return remaining + return min(float(requested_seconds), remaining) + try: # Get the target element element = page.locator(f".{element_name}") - element.wait_for(timeout=30000) # 30 second timeout + element.wait_for( + timeout=_timeout_seconds( + "dashboard_mount", + requested_seconds=30, + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + if report_execution_context + else 0.0 + ), + ) + * 1000 + ) + + mount_wait = _timeout_seconds( + "chart_holder_mount", + requested_seconds=None if report_execution_context else load_wait, + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + if report_execution_context + else 0.0 + ), + ) + try: + page.wait_for_function( + CHART_HOLDERS_MOUNTED_JS, + timeout=mount_wait * 1000, + ) + except PlaywrightTimeout: + holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) + elapsed, remaining = _deadline_values() + logger.warning( + "report_readiness_terminal url=%s expected_holders=%s " + "mounted_holders=%s ready_holders=0 elapsed_seconds=%.2f " + "remaining_seconds=%s effective_wait_seconds=%.2f%s " + "terminal_reason=zero_holders_timeout states=%s; " + "aborting before dimensions, capture, or delivery", + url, + ( + report_execution_context.expected_chart_count + if report_execution_context + else None + ), + len(holder_states), + elapsed, + f"{remaining:.2f}" if remaining is not None else None, + mount_wait, + context_suffix, + holder_states, + ) + readiness_timeout = True + raise # Get dashboard dimensions and position element_info = page.evaluate(f"""() => {{ @@ -339,42 +448,70 @@ def take_tiled_screenshot( # 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() + tile_load_wait = _timeout_seconds( + "chart_readiness", + requested_seconds=None if report_execution_context else load_wait, + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + if report_execution_context + else 0.0 + ), + ) try: page.wait_for_function( CHART_HOLDERS_READY_JS, - timeout=load_wait * 1000, + timeout=tile_load_wait * 1000, ) except PlaywrightTimeout: - elapsed = time.monotonic() - tile_wait_start + tile_elapsed = time.monotonic() - tile_wait_start unready_chart_holders = page.evaluate(FIND_UNREADY_CHART_HOLDERS_JS) + holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) + ready_states = {"rendered", "empty", "error", "virtualized"} + ready_holders = sum( + holder.get("state") in ready_states for holder in holder_states + ) + elapsed, remaining = _deadline_values() # 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), + "report_readiness_terminal url=%s expected_holders=%s " + "mounted_holders=%s ready_holders=%s tile=%s/%s " + "tile_elapsed_seconds=%.2f elapsed_seconds=%.2f " + "remaining_seconds=%s effective_wait_seconds=%.2f%s " + "terminal_reason=readiness_timeout unready_holders=%s " + "states=%s; aborting before capture or delivery", + url, + ( + report_execution_context.expected_chart_count + if report_execution_context + else None + ), + len(holder_states), + ready_holders, i + 1, num_tiles, - load_wait, + tile_elapsed, + elapsed, + f"{remaining:.2f}" if remaining is not None else None, + tile_load_wait, context_suffix, unready_chart_holders, + holder_states, ) readiness_timeout = True raise else: - elapsed = time.monotonic() - tile_wait_start + tile_elapsed = time.monotonic() - tile_wait_start logger.debug( - "Tile %s/%s chart holders ready after %.2fs (load_wait=%ss)%s", + "Tile %s/%s chart holders ready after %.2fs " + "(effective_wait=%.2fs)%s", i + 1, num_tiles, - elapsed, - load_wait, + tile_elapsed, + tile_load_wait, context_suffix, ) @@ -382,7 +519,22 @@ def take_tiled_screenshot( # The global animation wait before tiling only covers the first tile; # subsequent tiles need their own wait after data loads. if animation_wait > 0: - page.wait_for_timeout(animation_wait * 1000) + tile_animation_wait = float(animation_wait) + if report_execution_context: + try: + tile_animation_wait = min( + animation_wait, + _timeout_seconds( + "chart_animation", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ), + ) + except ReportExecutionBudgetExceededError: + tile_animation_wait = 0 + if tile_animation_wait > 0: + page.wait_for_timeout(tile_animation_wait * 1000) # Calculate what portion of the element we want to capture for this tile tile_start_in_element = i * tile_height @@ -420,17 +572,69 @@ def take_tiled_screenshot( } # Take screenshot with clipping to capture only this tile's content - tile_screenshot = page.screenshot(type="png", clip=clip) + capture_timeout = ( + _timeout_seconds( + "screenshot_capture", + reserve_seconds=( + report_execution_context.post_capture_reserve_seconds + if report_execution_context + else 0.0 + ), + ) + if report_execution_context or task_budget is not None + else None + ) + tile_screenshot = page.screenshot( + type="png", + clip=clip, + **( + {"timeout": capture_timeout * 1000} + if capture_timeout is not None + else {} + ), + ) screenshot_tiles.append(tile_screenshot) logger.debug("Captured tile %s/%s with clip %s", i + 1, num_tiles, clip) # Combine all tiles + holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) + if not isinstance(holder_states, list): + holder_states = [] + ready_states = {"rendered", "empty", "error", "virtualized"} + elapsed, remaining = _deadline_values() + logger.info( + "report_readiness_ready url=%s expected_holders=%s mounted_holders=%s " + "ready_holders=%s elapsed_seconds=%.2f remaining_seconds=%s%s", + url, + ( + report_execution_context.expected_chart_count + if report_execution_context + else None + ), + len(holder_states), + sum(holder.get("state") in ready_states for holder in holder_states), + elapsed, + f"{remaining:.2f}" if remaining is not None else None, + context_suffix, + ) logger.info("Combining screenshot tiles...") combined_screenshot = combine_screenshot_tiles(screenshot_tiles) return combined_screenshot + except (ReportExecutionBudgetExceededError, TiledScreenshotBudgetExceededError): + elapsed, remaining = _deadline_values() + logger.warning( + "report_capture_terminal url=%s elapsed_seconds=%.2f " + "remaining_seconds=%s%s terminal_reason=budget_exhausted; " + "aborting before unchecked capture or delivery", + url, + elapsed, + f"{remaining:.2f}" if remaining is not None else None, + context_suffix, + ) + raise except Exception as e: if readiness_timeout: # Let the per-tile readiness timeout propagate so the caller diff --git a/superset/utils/screenshots.py b/superset/utils/screenshots.py index 750ec54b597c..472354199b96 100644 --- a/superset/utils/screenshots.py +++ b/superset/utils/screenshots.py @@ -33,6 +33,7 @@ ) from superset.extensions import event_logger from superset.utils.hashing import hash_from_dict +from superset.utils.report_execution import ReportExecutionContext from superset.utils.urls import modify_url_query from superset.utils.webdriver import ( ChartStandaloneMode, @@ -214,11 +215,16 @@ def get_screenshot( user: User, window_size: WindowSize | None = None, log_context: str | None = None, + report_execution_context: ReportExecutionContext | None = None, ) -> bytes | None: driver = self.driver(window_size, user) try: self.screenshot = driver.get_screenshot( - self.url, self.element, user, log_context=log_context + self.url, + self.element, + user, + log_context=log_context, + report_execution_context=report_execution_context, ) finally: if isinstance(driver, WebDriverSelenium): diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index 5fd7d94418ab..acf01f0415a7 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -41,6 +41,9 @@ from selenium.webdriver.support.ui import WebDriverWait from superset.extensions import machine_auth_provider_factory +from superset.utils.report_execution import ( + ReportExecutionContext, +) from superset.utils.retries import retry_call from superset.utils.screenshot_utils import ( CHART_CONTAINER_READY_JS, @@ -220,6 +223,7 @@ def get_screenshot( element_name: str, user: User | None = None, log_context: str | None = None, + report_execution_context: ReportExecutionContext | None = None, ) -> bytes | None: """ Run webdriver and return a screenshot @@ -281,11 +285,19 @@ def find_unexpected_errors(page: Page) -> list[str]: return error_messages @staticmethod - def _get_screenshot(page: Page, element: Locator, element_name: str) -> bytes: + def _get_screenshot( + page: Page, + element: Locator, + element_name: str, + timeout_seconds: float | None = None, + ) -> bytes: + timeout_kwargs = ( + {"timeout": timeout_seconds * 1000} if timeout_seconds is not None else {} + ) if element_name == "standalone": - return page.screenshot(full_page=True) + return page.screenshot(full_page=True, **timeout_kwargs) else: - return element.screenshot() + return element.screenshot(**timeout_kwargs) @staticmethod def _wait_for_charts_ready( @@ -295,6 +307,7 @@ def _wait_for_charts_ready( element_name: str, log_context: str | None = None, screenshot_started_at: float | None = None, + report_execution_context: ReportExecutionContext | None = None, ) -> None: """ Wait for every viewport-visible chart holder to reach a terminal state @@ -316,6 +329,10 @@ def _wait_for_charts_ready( placeholders below the fold haven't mounted anything real yet by design and must not block this wait. """ + task_budget: float | None + remaining_budget: float | None + if report_execution_context: + log_context = report_execution_context.log_context context_suffix = f" [{log_context}]" if log_context else "" ready_states = {"rendered", "empty", "error", "virtualized"} initial_chart_holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) @@ -324,16 +341,47 @@ def _wait_for_charts_ready( for holder in initial_chart_holder_states if holder.get("state") not in ready_states ] - logger.debug( - "Chart holder states before readiness polling at url %s%s: %s", + expected_holders = ( + report_execution_context.expected_chart_count + if report_execution_context + else None + ) + initial_mounted_holders = len(initial_chart_holder_states) + initial_ready_holders = sum( + holder.get("state") in ready_states + for holder in initial_chart_holder_states + ) + deadline = ( + report_execution_context.deadline if report_execution_context else None + ) + deadline_elapsed = deadline.elapsed_seconds if deadline else None + deadline_remaining = deadline.remaining_seconds if deadline else None + logger.info( + "report_readiness_poll url=%s expected_holders=%s mounted_holders=%s " + "ready_holders=%s elapsed_seconds=%s remaining_seconds=%s%s states=%s", url, + expected_holders, + initial_mounted_holders, + initial_ready_holders, + f"{deadline_elapsed:.2f}" if deadline_elapsed is not None else None, + f"{deadline_remaining:.2f}" if deadline_remaining is not None else None, context_suffix, initial_chart_holder_states, ) if element_name == "standalone" and not initial_chart_holder_states: - logger.warning( - "dashboard capture proceeding with zero chart holders — " - "readiness gate inactive" + logger.info( + "report_readiness_waiting_for_mount url=%s expected_holders=%s " + "mounted_holders=0 ready_holders=0 elapsed_seconds=%s " + "remaining_seconds=%s%s", + url, + expected_holders, + f"{deadline_elapsed:.2f}" if deadline_elapsed is not None else None, + ( + f"{deadline_remaining:.2f}" + if deadline_remaining is not None + else None + ), + context_suffix, ) if initial_unready_chart_holders: logger.info( @@ -342,36 +390,47 @@ def _wait_for_charts_ready( context_suffix, initial_unready_chart_holders, ) - task_budget = resolve_screenshot_task_budget_seconds(log_context) - elapsed = ( - max(0.0, time.monotonic() - screenshot_started_at) - if task_budget is not None and screenshot_started_at is not None - else 0.0 - ) - remaining_budget = task_budget - elapsed if task_budget is not None else None - effective_load_wait = ( - min(float(load_wait), remaining_budget) - if remaining_budget is not None - else float(load_wait) - ) - if remaining_budget is not None and effective_load_wait <= 0: - logger.warning( - "Screenshot task budget exhausted before chart readiness wait " - "at url %s%s (%.2fs elapsed of %.2fs safe budget); unready chart " - "holders (chart id, state): %s; all chart holder states: %s. " - "Aborting before capture so cleanup and cache error transition " - "can complete.", - url, - context_suffix, - elapsed, - task_budget, - initial_unready_chart_holders, - initial_chart_holder_states, + if report_execution_context: + effective_load_wait = report_execution_context.deadline.timeout_seconds( + "chart_readiness", + reserve_seconds=report_execution_context.readiness_reserve_seconds, + ) + task_budget = report_execution_context.deadline.total_seconds + elapsed = report_execution_context.deadline.elapsed_seconds + remaining_budget = report_execution_context.deadline.remaining_seconds + else: + task_budget = resolve_screenshot_task_budget_seconds(log_context) + elapsed = ( + max(0.0, time.monotonic() - screenshot_started_at) + if task_budget is not None and screenshot_started_at is not None + else 0.0 ) - raise ScreenshotTaskBudgetExceededError( - f"Screenshot task budget of {task_budget:.2f}s exhausted " - "before chart readiness" + remaining_budget = ( + task_budget - elapsed if task_budget is not None else None ) + effective_load_wait = ( + min(float(load_wait), remaining_budget) + if remaining_budget is not None + else float(load_wait) + ) + if remaining_budget is not None and effective_load_wait <= 0: + logger.warning( + "Screenshot task budget exhausted before chart readiness wait " + "at url %s%s (%.2fs elapsed of %.2fs safe budget); unready chart " + "holders (chart id, state): %s; all chart holder states: %s. " + "Aborting before capture so cleanup and cache error transition " + "can complete.", + url, + context_suffix, + elapsed, + task_budget, + initial_unready_chart_holders, + initial_chart_holder_states, + ) + raise ScreenshotTaskBudgetExceededError( + f"Screenshot task budget of {task_budget:.2f}s exhausted " + "before chart readiness" + ) logger.debug( "Waiting for all chart holders to reach a terminal state at " "url: %s (SCREENSHOT_LOAD_WAIT=%ss, effective_wait=%.2fs, " @@ -400,23 +459,56 @@ def _wait_for_charts_ready( for holder in chart_holder_states if holder.get("state") not in ready_states ] + mounted_holders = len(chart_holder_states) + ready_holders = sum( + holder.get("state") in ready_states for holder in chart_holder_states + ) + deadline_elapsed = deadline.elapsed_seconds if deadline else elapsed + deadline_remaining = ( + deadline.remaining_seconds if deadline else remaining_budget + ) logger.warning( - "Timed out waiting for %s chart container(s) to become ready " - "at url %s (SCREENSHOT_LOAD_WAIT=%ss, effective_wait=%.2fs)%s; " - "unready chart " - "holders (chart id, state): %s; all chart holder states: %s. " - "Aborting screenshot rather " - "than capturing a blank or partially-loaded dashboard.", - len(unready_chart_holders), + "report_readiness_terminal url=%s expected_holders=%s " + "mounted_holders=%s ready_holders=%s elapsed_seconds=%.2f " + "remaining_seconds=%s effective_wait_seconds=%.2f%s " + "terminal_reason=readiness_timeout unready_holders=%s states=%s; " + "aborting before capture or delivery", url, - load_wait, + expected_holders, + mounted_holders, + ready_holders, + deadline_elapsed, + ( + f"{deadline_remaining:.2f}" + if deadline_remaining is not None + else None + ), effective_load_wait, context_suffix, unready_chart_holders, chart_holder_states, ) raise - logger.debug("All chart holders ready at url: %s%s", url, context_suffix) + chart_holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) + mounted_holders = len(chart_holder_states) + ready_holders = sum( + holder.get("state") in ready_states for holder in chart_holder_states + ) + deadline_elapsed = deadline.elapsed_seconds if deadline else elapsed + deadline_remaining = ( + deadline.remaining_seconds if deadline else remaining_budget + ) + logger.info( + "report_readiness_ready url=%s expected_holders=%s mounted_holders=%s " + "ready_holders=%s elapsed_seconds=%.2f remaining_seconds=%s%s", + url, + expected_holders, + mounted_holders, + ready_holders, + deadline_elapsed, + (f"{deadline_remaining:.2f}" if deadline_remaining is not None else None), + context_suffix, + ) def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # noqa: C901 self, @@ -424,8 +516,15 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n element_name: str, user: User | None = None, log_context: str | None = None, + report_execution_context: ReportExecutionContext | None = None, ) -> bytes | None: screenshot_started_at = time.monotonic() + if report_execution_context: + log_context = report_execution_context.log_context + report_execution_context.deadline.available_seconds( + "browser_setup", + reserve_seconds=report_execution_context.readiness_reserve_seconds, + ) if not PLAYWRIGHT_AVAILABLE: logger.info( "Playwright not available - falling back to Selenium. " @@ -455,9 +554,24 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n img: bytes | None = None try: try: + navigation_timeout = ( + report_execution_context.deadline.timeout_seconds( + "browser_navigation", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ) + if report_execution_context + else None + ) page.goto( url, wait_until=app.config["SCREENSHOT_PLAYWRIGHT_WAIT_EVENT"], + **( + {"timeout": navigation_timeout * 1000} + if navigation_timeout is not None + else {} + ), ) except PlaywrightTimeout: logger.exception( @@ -467,6 +581,16 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n ) selenium_headstart = app.config["SCREENSHOT_SELENIUM_HEADSTART"] + if report_execution_context: + selenium_headstart = min( + selenium_headstart, + report_execution_context.deadline.available_seconds( + "browser_headstart", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ), + ) logger.debug("Sleeping for %i seconds", selenium_headstart) page.wait_for_timeout(selenium_headstart * 1000) element: Locator @@ -477,7 +601,23 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n "Wait for the presence of %s at url: %s", element_name, url ) element = page.locator(f".{element_name}") - element.wait_for() + element_wait_timeout = ( + report_execution_context.deadline.timeout_seconds( + "dashboard_mount", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ) + if report_execution_context + else None + ) + element.wait_for( + **( + {"timeout": element_wait_timeout * 1000} + if element_wait_timeout is not None + else {} + ) + ) except PlaywrightTimeout: logger.exception("Timed out requesting url %s", url) raise @@ -487,7 +627,23 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n logger.debug("Wait for chart containers to draw at url: %s", url) slice_container_locator = page.locator(".chart-container") for slice_container_elem in slice_container_locator.all(): - slice_container_elem.wait_for() + slice_wait_timeout = ( + report_execution_context.deadline.timeout_seconds( + "chart_mount", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ) + if report_execution_context + else None + ) + slice_container_elem.wait_for( + **( + {"timeout": slice_wait_timeout * 1000} + if slice_wait_timeout is not None + else {} + ) + ) except PlaywrightTimeout: logger.exception( "Timed out waiting for chart containers to draw at url %s", @@ -510,9 +666,18 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n tiled_enabled = app.config.get("SCREENSHOT_TILED_ENABLED", False) if tiled_enabled: - chart_count = page.evaluate( + mounted_chart_count = page.evaluate( 'document.querySelectorAll(".chart-container").length' ) + expected_chart_count = ( + report_execution_context.expected_chart_count + if report_execution_context + else None + ) + chart_count = max( + mounted_chart_count, + expected_chart_count or 0, + ) dashboard_height = page.evaluate( f"""() => {{ const target = document.querySelector(\".{element_name}\"); @@ -538,17 +703,22 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n ) # Use tiled screenshots for large dashboards - use_tiled = ( - chart_count >= chart_threshold - or dashboard_height > height_threshold - ) and dashboard_height > tile_height + use_tiled = chart_count >= chart_threshold or ( + dashboard_height > height_threshold + and dashboard_height > tile_height + ) if use_tiled: logger.info( - "Large dashboard detected: %s charts, %spx height. " - "Using tiled screenshots.", + "Large dashboard detected: expected_charts=%s " + "mounted_chart_containers=%s effective_chart_count=%s " + "height_px=%s url=%s%s; using tiled screenshots", + expected_chart_count, + mounted_chart_count, chart_count, dashboard_height, + url, + f" [{log_context}]" if log_context else "", ) # set viewport height to tile height for easier calculations page.set_viewport_size( @@ -561,16 +731,18 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n load_wait=self._screenshot_load_wait, animation_wait=selenium_animation_wait, log_context=log_context, + report_execution_context=report_execution_context, + url=url, ) if not img: logger.warning( - ( - "Tiled screenshot failed, " - "falling back to standard screenshot" - ) + "Tiled screenshot failed for url %s%s and no safe " + "fallback exists; terminal_reason=tiled_capture_failed", + url, + f" [{log_context}]" if log_context else "", ) - img = WebDriverPlaywright._get_screenshot( - page, element, element_name + raise PlaywrightTimeout( + f"Tiled screenshot failed for url {url}" ) logger.debug( "Tiled screenshot result: %d bytes for url: %s", @@ -596,8 +768,19 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n element_name, log_context=log_context, screenshot_started_at=screenshot_started_at, + report_execution_context=report_execution_context, ) if selenium_animation_wait > 0: + if report_execution_context: + selenium_animation_wait = min( + selenium_animation_wait, + report_execution_context.deadline.available_seconds( + "chart_animation", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ), + ) logger.debug( "Wait %i seconds for chart animation", selenium_animation_wait, @@ -608,8 +791,21 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n url, user.username if user else "None", ) + capture_timeout = ( + report_execution_context.deadline.timeout_seconds( + "screenshot_capture", + reserve_seconds=( + report_execution_context.post_capture_reserve_seconds + ), + ) + if report_execution_context + else None + ) img = WebDriverPlaywright._get_screenshot( - page, element, element_name + page, + element, + element_name, + timeout_seconds=capture_timeout, ) logger.debug( "Screenshot result: %d bytes for url: %s", @@ -632,8 +828,19 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n element_name, log_context=log_context, screenshot_started_at=screenshot_started_at, + report_execution_context=report_execution_context, ) if selenium_animation_wait > 0: + if report_execution_context: + selenium_animation_wait = min( + selenium_animation_wait, + report_execution_context.deadline.available_seconds( + "chart_animation", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ), + ) logger.debug( "Wait %i seconds for chart animation", selenium_animation_wait, @@ -644,8 +851,21 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n url, user.username if user else "None", ) + capture_timeout = ( + report_execution_context.deadline.timeout_seconds( + "screenshot_capture", + reserve_seconds=( + report_execution_context.post_capture_reserve_seconds + ), + ) + if report_execution_context + else None + ) img = WebDriverPlaywright._get_screenshot( - page, element, element_name + page, + element, + element_name, + timeout_seconds=capture_timeout, ) logger.debug( "Screenshot result: %d bytes for url: %s", @@ -922,7 +1142,24 @@ def get_screenshot( # noqa: C901 element_name: str, user: User | None = None, log_context: str | None = None, + report_execution_context: ReportExecutionContext | None = None, ) -> bytes | None: + if report_execution_context: + log_context = report_execution_context.log_context + + def phase_timeout( + phase: str, + requested_seconds: float | None, + reserve_seconds: float = 0.0, + ) -> float: + if report_execution_context: + return report_execution_context.deadline.timeout_seconds( + phase, + requested_seconds=requested_seconds, + reserve_seconds=reserve_seconds, + ) + return float(requested_seconds or self._screenshot_load_wait) + # If a user is passed explicitly and differs from the stored user, # update and re-authenticate if user and user != self._user: @@ -930,9 +1167,26 @@ def get_screenshot( # noqa: C901 if self._driver: self._destroy() driver = self.driver + if report_execution_context: + driver.set_page_load_timeout( + phase_timeout( + "browser_navigation", + None, + report_execution_context.readiness_reserve_seconds, + ) + ) driver.get(url) img: bytes | None = None selenium_headstart = app.config["SCREENSHOT_SELENIUM_HEADSTART"] + if report_execution_context: + selenium_headstart = min( + selenium_headstart, + phase_timeout( + "browser_headstart", + None, + report_execution_context.readiness_reserve_seconds, + ), + ) logger.debug("Sleeping for %i seconds", selenium_headstart) sleep(selenium_headstart) @@ -946,57 +1200,168 @@ def get_screenshot( # noqa: C901 logger.debug( "Wait for the presence of %s at url: %s", element_name, url ) - element = WebDriverWait(driver, self._screenshot_locate_wait).until( - EC.presence_of_element_located((By.CLASS_NAME, element_name)) - ) + element = WebDriverWait( + driver, + phase_timeout( + "dashboard_mount", + self._screenshot_locate_wait, + ( + report_execution_context.readiness_reserve_seconds + if report_execution_context + else 0.0 + ), + ), + ).until(EC.presence_of_element_located((By.CLASS_NAME, element_name))) except TimeoutException: logger.warning( "Selenium timed out requesting url %s", url, exc_info=True ) raise - try: - # chart containers didn't render - logger.debug("Wait for chart containers to draw at url: %s", url) - WebDriverWait(driver, self._screenshot_locate_wait).until( - EC.visibility_of_all_elements_located( - (By.CLASS_NAME, "chart-container") - ) + if element_name == "standalone": + readiness_timeout = phase_timeout( + "chart_readiness", + None if report_execution_context else self._screenshot_load_wait, + ( + report_execution_context.readiness_reserve_seconds + if report_execution_context + else 0.0 + ), ) - except TimeoutException: - logger.info("Timeout Exception caught") - # Fallback to allow a screenshot of an empty dashboard try: - WebDriverWait(driver, 0).until( + WebDriverWait(driver, readiness_timeout).until( + lambda webdriver: webdriver.execute_script( + f"return ({CHART_HOLDERS_READY_JS})()" + ) + ) + holder_states = driver.execute_script( + f"return ({FIND_CHART_HOLDER_STATES_JS})()" + ) + ready_states = {"rendered", "empty", "error", "virtualized"} + deadline = ( + report_execution_context.deadline + if report_execution_context + else None + ) + logger.info( + "report_readiness_ready url=%s expected_holders=%s " + "mounted_holders=%s ready_holders=%s elapsed_seconds=%s " + "remaining_seconds=%s%s", + url, + ( + report_execution_context.expected_chart_count + if report_execution_context + else None + ), + len(holder_states), + sum( + holder.get("state") in ready_states + for holder in holder_states + ), + (f"{deadline.elapsed_seconds:.2f}" if deadline else None), + (f"{deadline.remaining_seconds:.2f}" if deadline else None), + f" [{log_context}]" if log_context else "", + ) + except TimeoutException: + holder_states = driver.execute_script( + f"return ({FIND_CHART_HOLDER_STATES_JS})()" + ) + ready_states = {"rendered", "empty", "error", "virtualized"} + ready_holders = sum( + holder.get("state") in ready_states for holder in holder_states + ) + deadline = ( + report_execution_context.deadline + if report_execution_context + else None + ) + logger.warning( + "report_readiness_terminal url=%s expected_holders=%s " + "mounted_holders=%s ready_holders=%s elapsed_seconds=%s " + "remaining_seconds=%s effective_wait_seconds=%.2f%s " + "terminal_reason=readiness_timeout states=%s; " + "aborting before capture or delivery", + url, + ( + report_execution_context.expected_chart_count + if report_execution_context + else None + ), + len(holder_states), + ready_holders, + (f"{deadline.elapsed_seconds:.2f}" if deadline else None), + (f"{deadline.remaining_seconds:.2f}" if deadline else None), + readiness_timeout, + f" [{log_context}]" if log_context else "", + holder_states, + ) + raise + else: + try: + # chart containers didn't render + logger.debug("Wait for chart containers to draw at url: %s", url) + WebDriverWait( + driver, + phase_timeout( + "chart_mount", + self._screenshot_locate_wait, + ( + report_execution_context.readiness_reserve_seconds + if report_execution_context + else 0.0 + ), + ), + ).until( EC.visibility_of_all_elements_located( - (By.CLASS_NAME, "grid-container") + (By.CLASS_NAME, "chart-container") ) ) - except Exception: + except TimeoutException: logger.warning( - "Selenium timed out waiting for dashboard to draw at url %s", + "Selenium timed out waiting for chart to draw at url %s", url, exc_info=True, ) raise - try: - # charts took too long to load - logger.debug( - "Wait for loading element of charts to be gone at url: %s", url - ) - WebDriverWait(driver, self._screenshot_load_wait).until_not( - EC.presence_of_all_elements_located((By.CLASS_NAME, "loading")) - ) - except TimeoutException: - logger.warning( - "Selenium timed out waiting for charts to load at url %s", - url, - exc_info=True, - ) - raise + try: + # charts took too long to load + logger.debug( + "Wait for loading element of charts to be gone at url: %s", + url, + ) + WebDriverWait( + driver, + phase_timeout( + "chart_readiness", + self._screenshot_load_wait, + ( + report_execution_context.readiness_reserve_seconds + if report_execution_context + else 0.0 + ), + ), + ).until_not( + EC.presence_of_all_elements_located((By.CLASS_NAME, "loading")) + ) + except TimeoutException: + logger.warning( + "Selenium timed out waiting for charts to load at url %s", + url, + exc_info=True, + ) + raise selenium_animation_wait = app.config["SCREENSHOT_SELENIUM_ANIMATION_WAIT"] + if report_execution_context: + selenium_animation_wait = min( + selenium_animation_wait, + phase_timeout( + "chart_animation", + None, + report_execution_context.readiness_reserve_seconds, + ), + ) logger.debug("Wait %i seconds for chart animation", selenium_animation_wait) sleep(selenium_animation_wait) logger.debug( @@ -1015,6 +1380,12 @@ def get_screenshot( # noqa: C901 unexpected_errors, ) + if report_execution_context: + phase_timeout( + "screenshot_capture", + None, + report_execution_context.post_capture_reserve_seconds, + ) img = element.screenshot_as_png except TimeoutException: # Already logged at WARNING in the inner handlers above diff --git a/tests/integration_tests/reports/scheduler_tests.py b/tests/integration_tests/reports/scheduler_tests.py index 9bb2528f6f75..f8cccc1dc794 100644 --- a/tests/integration_tests/reports/scheduler_tests.py +++ b/tests/integration_tests/reports/scheduler_tests.py @@ -17,6 +17,7 @@ from random import randint from unittest.mock import MagicMock, patch +from uuid import UUID import pytest from freezegun import freeze_time @@ -108,6 +109,25 @@ def test_scheduler_celery_timeout_utc(execute_mock, editors): db.session.commit() +@pytest.mark.usefixtures("app_context") +@patch("superset.tasks.scheduler.execute.apply_async") +def test_scheduler_report_timeout_uses_end_to_end_budget(execute_mock, editors): + report_schedule = insert_report_schedule( + type=ReportScheduleType.REPORT, + name="dashboard report", + crontab="0 9 * * *", + timezone="UTC", + editors=editors, + ) + + with freeze_time("2020-01-01T09:00:00Z"): + scheduler() + assert execute_mock.call_args[1]["soft_time_limit"] == 900 + assert execute_mock.call_args[1]["time_limit"] == 930 + db.session.delete(report_schedule) + db.session.commit() + + @pytest.mark.usefixtures("app_context") @patch("superset.tasks.scheduler.execute.apply_async") def test_scheduler_celery_no_timeout_utc(execute_mock, editors): @@ -252,3 +272,27 @@ def test_log_task_failure_without_sender(logger_mock): logger_mock.exception.assert_called_once_with( "Celery task %s failed: %s", "Unknown", mock_exception, exc_info=mock_einfo ) + + +@patch("superset.tasks.scheduler.mark_report_execution_terminal_error") +@patch("superset.tasks.scheduler.logger") +def test_log_task_failure_cleans_up_report_working_state( + logger_mock, + cleanup_mock, +): + task = MagicMock() + task.name = "reports.execute" + execution_id = "084e7ee6-5557-4ecd-9632-b7f39c9ec524" + + log_task_failure( + sender=task, + task_id=execution_id, + exception=RuntimeError("worker lost"), + args=(11,), + ) + + cleanup_mock.assert_called_once_with( + 11, + UUID(execution_id), + "celery_task_failure:RuntimeError", + ) diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index da38081a7d01..0d7d654e538b 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -44,6 +44,7 @@ ) from superset.commands.report.execute import ( BaseReportState, + mark_report_execution_terminal_error, ReportNotTriggeredErrorState, ReportScheduleStateMachine, ReportSuccessState, @@ -63,6 +64,11 @@ ) from superset.subjects.types import SubjectType from superset.utils.core import HeaderDataType +from superset.utils.report_execution import ( + ReportExecutionBudgetExceededError, + ReportExecutionContext, + ReportExecutionDeadline, +) from superset.utils.screenshots import ChartScreenshot from tests.integration_tests.conftest import with_feature_flags @@ -2250,10 +2256,15 @@ def test_working_state_timeout_raises_timeout_error(mocker: MockerFixture) -> No mock_log = mocker.Mock() mock_log.end_dttm = datetime.utcnow() - timedelta(hours=2) + mock_log.uuid = uuid4() mocker.patch( "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", return_value=mock_log, ) + cleanup = mocker.patch( + "superset.commands.report.execute.mark_report_execution_terminal_error", + return_value=True, + ) mocker.patch.object(state, "update_report_schedule_and_log") with pytest.raises(ReportScheduleWorkingTimeoutError): @@ -2263,6 +2274,11 @@ def test_working_state_timeout_raises_timeout_error(mocker: MockerFixture) -> No ReportState.ERROR, error_message=str(ReportScheduleWorkingTimeoutError()), ) + cleanup.assert_called_once_with( + state._report_schedule.id, + mock_log.uuid, + "working_timeout_recovery", + ) def test_working_state_still_working_raises_previous_working( @@ -2282,6 +2298,118 @@ def test_working_state_still_working_raises_previous_working( ) +def test_working_timeout_replay_promotes_original_execution_without_duplicate_log( + mocker: MockerFixture, +) -> None: + state = _make_state_instance( + mocker, + ReportWorkingState, + schedule_type=ReportScheduleType.REPORT, + last_state=ReportState.WORKING, + ) + mocker.patch.object(state, "is_on_working_timeout", return_value=True) + working_log = mocker.Mock() + working_log.uuid = state._execution_id + working_log.end_dttm = datetime.utcnow() - timedelta(minutes=20) + mocker.patch( + "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", + return_value=working_log, + ) + cleanup = mocker.patch( + "superset.commands.report.execute.mark_report_execution_terminal_error", + return_value=True, + ) + update = mocker.patch.object(state, "update_report_schedule_and_log") + + with pytest.raises(ReportScheduleWorkingTimeoutError): + state.next() + + cleanup.assert_called_once() + update.assert_not_called() + + +def test_new_report_execution_proceeds_after_stale_working_cleanup( + mocker: MockerFixture, +) -> None: + """A stale execution must not consume the next distinct scheduled run.""" + state = _make_state_instance( + mocker, + ReportWorkingState, + schedule_type=ReportScheduleType.REPORT, + last_state=ReportState.WORKING, + ) + mocker.patch.object(state, "is_on_working_timeout", return_value=True) + working_log = mocker.Mock() + working_log.uuid = uuid4() + working_log.end_dttm = datetime.utcnow() - timedelta(minutes=20) + mocker.patch( + "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", + return_value=working_log, + ) + cleanup = mocker.patch( + "superset.commands.report.execute.mark_report_execution_terminal_error", + return_value=True, + ) + recovered_next = mocker.patch.object(ReportNotTriggeredErrorState, "next") + update = mocker.patch.object(state, "update_report_schedule_and_log") + + state.next() + + cleanup.assert_called_once_with( + state._report_schedule.id, + working_log.uuid, + "working_timeout_recovery", + ) + recovered_next.assert_called_once() + update.assert_not_called() + + +def test_report_working_state_recovery_is_bounded_by_execution_budget( + app: SupersetApp, + mocker: MockerFixture, +) -> None: + """A lost report worker cannot leave WORKING blocked for its legacy hour.""" + state = _make_state_instance( + mocker, + ReportWorkingState, + schedule_type=ReportScheduleType.REPORT, + last_state=ReportState.WORKING, + working_timeout=3600, + ) + working_log = mocker.Mock() + working_log.end_dttm = datetime.utcnow() - timedelta(minutes=20) + mocker.patch( + "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", + return_value=working_log, + ) + + assert app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] == 900 + assert state.is_on_working_timeout() + + +def test_soft_timeout_transitions_report_out_of_working( + mocker: MockerFixture, +) -> None: + state = _make_state_instance( + mocker, + ReportNotTriggeredErrorState, + schedule_type=ReportScheduleType.REPORT, + ) + mocker.patch.object(state, "send", side_effect=SoftTimeLimitExceeded()) + mock_update = mocker.patch.object(state, "update_report_schedule_and_log") + send_error = mocker.patch.object(state, "send_error") + + with pytest.raises(SoftTimeLimitExceeded): + state.next() + + assert mock_update.call_args_list[0] == mocker.call(ReportState.WORKING) + assert mock_update.call_args_list[1] == mocker.call( + ReportState.ERROR, + error_message="celery_soft_timeout", + ) + send_error.assert_not_called() + + def test_success_state_grace_period_returns_without_sending( mocker: MockerFixture, ) -> None: @@ -2484,6 +2612,50 @@ def test_create_log_success_commits(mocker: MockerFixture) -> None: mock_db.session.rollback.assert_not_called() +def test_failure_hook_cleanup_promotes_working_log_to_terminal_error( + app: SupersetApp, + mocker: MockerFixture, +) -> None: + execution_id = UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524") + schedule = mocker.Mock(spec=ReportSchedule) + schedule.last_state = ReportState.WORKING + schedule.dashboard_id = 805 + schedule.chart_id = None + working_log = mocker.Mock() + working_log.uuid = execution_id + working_log.report_schedule = schedule + + mock_db = mocker.patch("superset.commands.report.execute.db") + filtered_query = mock_db.session.query.return_value.filter.return_value + filtered_query.first.return_value = working_log + filtered_query.order_by.return_value.first.return_value = working_log + + assert mark_report_execution_terminal_error( + 11, + execution_id, + "celery_task_failure:WorkerLostError", + ) + assert working_log.state == ReportState.ERROR + assert working_log.error_message == "celery_task_failure:WorkerLostError" + assert schedule.last_state == ReportState.ERROR + mock_db.session.commit.assert_called_once() + + +def test_failure_hook_cleanup_is_idempotent( + app: SupersetApp, + mocker: MockerFixture, +) -> None: + mock_db = mocker.patch("superset.commands.report.execute.db") + mock_db.session.query.return_value.filter.return_value.first.return_value = None + + assert not mark_report_execution_terminal_error( + 11, + UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + "celery_task_failure:WorkerLostError", + ) + mock_db.session.commit.assert_not_called() + + def test_success_state_report_sends_and_logs_success( mocker: MockerFixture, ) -> None: @@ -2507,6 +2679,57 @@ def test_success_state_report_sends_and_logs_success( ] +def test_delivery_budget_exhaustion_does_not_send_notification( + mocker: MockerFixture, +) -> None: + state = _make_state_instance( + mocker, + BaseReportState, + schedule_type=ReportScheduleType.REPORT, + ) + deadline = ReportExecutionDeadline( + total_seconds=900, + started_at=0, + _clock=lambda: 880, + ) + state._report_execution_context = ReportExecutionContext( + execution_id=state._execution_id, + report_schedule_id=11, + dashboard_id=805, + expected_chart_count=52, + deadline=deadline, + cleanup_reserve_seconds=30, + ) + recipient = mocker.Mock(spec=ReportRecipients) + notification = mocker.patch( + "superset.commands.report.execute.create_notification" + ).return_value + + with pytest.raises(ReportExecutionBudgetExceededError): + state._send(mocker.Mock(), [recipient]) + + notification.send.assert_not_called() + + +def test_incomplete_capture_never_reaches_delivery(mocker: MockerFixture) -> None: + state = _make_state_instance( + mocker, + BaseReportState, + schedule_type=ReportScheduleType.REPORT, + ) + mocker.patch.object( + state, + "_get_notification_content", + side_effect=ReportScheduleScreenshotFailedError("not ready"), + ) + send_notification = mocker.patch.object(state, "_send") + + with pytest.raises(ReportScheduleScreenshotFailedError): + state.send() + + send_notification.assert_not_called() + + def test_success_state_error_logged_when_send_error_raises( mocker: MockerFixture, ) -> None: diff --git a/tests/unit_tests/commands/report/test_execute_now.py b/tests/unit_tests/commands/report/test_execute_now.py index e69ed0734fd1..de6665d562db 100644 --- a/tests/unit_tests/commands/report/test_execute_now.py +++ b/tests/unit_tests/commands/report/test_execute_now.py @@ -28,14 +28,20 @@ ReportScheduleNotFoundError, ) from superset.exceptions import SupersetSecurityException +from superset.reports.models import ReportScheduleType -def _make_mock_schedule(*, working_timeout: int | None = None) -> MagicMock: +def _make_mock_schedule( + *, + working_timeout: int | None = None, + schedule_type: ReportScheduleType = ReportScheduleType.ALERT, +) -> MagicMock: """Return a minimal mock ReportSchedule.""" mock_schedule = MagicMock() mock_schedule.id = 1 mock_schedule.name = "Test Report" mock_schedule.working_timeout = working_timeout + mock_schedule.type = schedule_type return mock_schedule @@ -196,3 +202,37 @@ def test_execute_now_sets_time_limit_when_working_timeout_configured() -> None: assert keyword_args["time_limit"] == 310 # working_timeout(300) + LAG(10) assert "soft_time_limit" in keyword_args assert keyword_args["soft_time_limit"] == 305 # working_timeout(300) + SOFT_LAG(5) + + +def test_execute_now_report_uses_end_to_end_budget_time_limits() -> None: + mock_task = MagicMock() + mock_scheduler = MagicMock() + mock_scheduler.execute = mock_task + + with patch.dict(sys.modules, {"superset.tasks.scheduler": mock_scheduler}): + from superset.commands.report.execute_now import ExecuteReportScheduleNowCommand + + with ( + patch( + "superset.commands.report.execute_now.ReportScheduleDAO.find_by_id", + return_value=_make_mock_schedule( + working_timeout=3600, + schedule_type=ReportScheduleType.REPORT, + ), + ), + patch( + "superset.commands.report.execute_now.security_manager" + ".raise_for_editorship" + ), + patch("superset.commands.report.execute_now.current_app") as mock_app, + ): + mock_app.config = { + "ALERT_REPORTS_WORKING_TIME_OUT_KILL": True, + "ALERT_REPORTS_EXECUTION_BUDGET_SECONDS": 900, + "ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS": 30, + } + ExecuteReportScheduleNowCommand(1).run() + + _, keyword_args = mock_task.apply_async.call_args + assert keyword_args["soft_time_limit"] == 900 + assert keyword_args["time_limit"] == 930 diff --git a/tests/unit_tests/utils/test_report_execution.py b/tests/unit_tests/utils/test_report_execution.py new file mode 100644 index 000000000000..15d775945a33 --- /dev/null +++ b/tests/unit_tests/utils/test_report_execution.py @@ -0,0 +1,106 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from uuid import UUID + +import pytest + +from superset.utils.report_execution import ( + get_report_task_timeout_options, + ReportExecutionBudgetExceededError, + ReportExecutionContext, + ReportExecutionDeadline, +) + + +def test_report_deadline_derives_phase_timeout_from_one_clock() -> None: + clock_value = 100.0 + deadline = ReportExecutionDeadline( + total_seconds=900, + started_at=0, + _clock=lambda: clock_value, + ) + context = ReportExecutionContext( + execution_id=UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + report_schedule_id=7, + deadline=deadline, + capture_reserve_seconds=60, + delivery_reserve_seconds=120, + cleanup_reserve_seconds=30, + ) + + assert deadline.elapsed_seconds == 100 + assert deadline.remaining_seconds == 800 + assert context.readiness_reserve_seconds == 210 + assert ( + deadline.timeout_seconds( + "chart_readiness", + reserve_seconds=context.readiness_reserve_seconds, + ) + == 590 + ) + assert ( + deadline.timeout_seconds( + "screenshot_capture", + reserve_seconds=context.post_capture_reserve_seconds, + ) + == 650 + ) + assert ( + deadline.timeout_seconds( + "notification_delivery", + reserve_seconds=context.cleanup_reserve_seconds, + ) + == 770 + ) + + +def test_report_deadline_exhaustion_names_phase() -> None: + deadline = ReportExecutionDeadline( + total_seconds=900, + started_at=0, + _clock=lambda: 700, + ) + + with pytest.raises( + ReportExecutionBudgetExceededError, + match="before chart_readiness", + ): + deadline.timeout_seconds( + "chart_readiness", + reserve_seconds=210, + ) + + +def test_report_task_limits_align_soft_timeout_with_budget() -> None: + config = { + "ALERT_REPORTS_WORKING_TIME_OUT_KILL": True, + "ALERT_REPORTS_EXECUTION_BUDGET_SECONDS": 900, + "ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS": 30, + "ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG": 1, + "ALERT_REPORTS_WORKING_TIME_OUT_LAG": 10, + } + + assert get_report_task_timeout_options( + is_report=True, + working_timeout=3600, + config=config, + ) == {"soft_time_limit": 900, "time_limit": 930} + assert get_report_task_timeout_options( + is_report=False, + working_timeout=3600, + config=config, + ) == {"soft_time_limit": 3601, "time_limit": 3610} diff --git a/tests/unit_tests/utils/test_screenshot_utils.py b/tests/unit_tests/utils/test_screenshot_utils.py index 438290015968..142efe43ebc8 100644 --- a/tests/unit_tests/utils/test_screenshot_utils.py +++ b/tests/unit_tests/utils/test_screenshot_utils.py @@ -194,6 +194,69 @@ def test_successful_tiled_screenshot(self, mock_page): # Should have called combine function mock_combine.assert_called_once() + def test_slow_holder_mount_is_polled_before_dimensions_and_capture( + self, + mock_page, + ): + """Tiling waits for React to mount a holder before measuring the dashboard.""" + events: list[str] = [] + element_info = {"height": 1000, "top": 0, "left": 0, "width": 800} + wait_calls = 0 + + def wait_for_function(*args, **kwargs): + nonlocal wait_calls + events.append("mount" if wait_calls == 0 else "ready") + wait_calls += 1 + + def evaluate(script): + if "scrollWidth" in script: + events.append("dimensions") + return element_info + if "window.scrollTo" in script: + return None + return [{"chartId": "7", "state": "rendered"}] + + def screenshot(**kwargs): + events.append("capture") + return b"tile" + + mock_page.wait_for_function.side_effect = wait_for_function + mock_page.evaluate.side_effect = evaluate + mock_page.screenshot.side_effect = screenshot + + with patch( + "superset.utils.screenshot_utils.combine_screenshot_tiles", + return_value=b"combined", + ): + result = take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + load_wait=30, + ) + + assert result == b"combined" + assert events == ["mount", "dimensions", "ready", "capture"] + + def test_zero_holders_timeout_before_dimensions_or_capture(self, mock_page): + """An empty DOM cannot vacuously pass the tiled readiness gate.""" + from superset.utils.screenshot_utils import PlaywrightTimeout + + mock_page.wait_for_function.side_effect = PlaywrightTimeout("zero holders") + mock_page.evaluate.return_value = [] + + with pytest.raises(PlaywrightTimeout): + take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + load_wait=30, + ) + + assert mock_page.evaluate.call_count == 1 + assert "state: 'rendered'" in mock_page.evaluate.call_args.args[0] + mock_page.screenshot.assert_not_called() + def test_element_not_found_returns_none(self): """Test that missing element returns None.""" mock_page = MagicMock() @@ -362,8 +425,8 @@ def test_scroll_positions_calculated_correctly(self, mock_page): # First call is for dimensions, subsequent are for scrolling evaluate_calls = mock_page.evaluate.call_args_list - # Should have 1 dimension query + 3 scroll calls - assert len(evaluate_calls) == 4 + # 1 dimension query + 3 scroll calls + final holder diagnostics + assert len(evaluate_calls) == 5 # First call is for dimensions (contains querySelector) assert "querySelector" in str(evaluate_calls[0]) @@ -397,11 +460,14 @@ def test_per_tile_readiness_wait_uses_viewport_check(self, mock_page): mock_page, "dashboard", tile_height=2000, load_wait=30 ) - # 3 tiles → 3 wait_for_function calls, one per tile - assert mock_page.wait_for_function.call_count == 3 + # One initial holder-mount gate, then one readiness poll per tile. + assert mock_page.wait_for_function.call_count == 4 # Each call uses viewport-scoped JS and the load_wait timeout - for call in mock_page.wait_for_function.call_args_list: + mount_call, *tile_calls = mock_page.wait_for_function.call_args_list + assert "length > 0" in mount_call.args[0] + assert mount_call.kwargs["timeout"] == 30 * 1000 + for call in tile_calls: js = call[0][0] assert "getBoundingClientRect" in js assert "window.innerHeight" in js @@ -418,11 +484,12 @@ def test_per_tile_readiness_timeout_raises_and_skips_capture(self, mock_page): from superset.utils.screenshot_utils import PlaywrightTimeout timeout = PlaywrightTimeout("Timeout waiting for chart holders") - mock_page.wait_for_function.side_effect = timeout + mock_page.wait_for_function.side_effect = [None, 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 + [{"chartId": "42", "state": "waiting_on_database"}], # unready + [{"chartId": "42", "state": "waiting_on_database"}], # all states ] with patch("superset.utils.screenshot_utils.logger") as mock_logger: @@ -436,9 +503,8 @@ def test_per_tile_readiness_timeout_raises_and_skips_capture(self, mock_page): # 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 + # The mount gate passes and only the first tile readiness poll runs. + assert mock_page.wait_for_function.call_count == 2 # A chart failing to load in time is a customer chart-loading issue, # not a Superset system fault -- WARNING, not ERROR (#38130, #38441). @@ -447,29 +513,33 @@ def test_per_tile_readiness_timeout_raises_and_skips_capture(self, mock_page): 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 + assert warning_args[3] == 1 # mounted holders + assert warning_args[4] == 0 # ready holders + assert warning_args[5] == 1 # tile index + assert warning_args[6] == 3 # total tiles + assert isinstance(warning_args[7], float) # tile elapsed + assert isinstance(warning_args[8], float) # total elapsed + assert warning_args[10] == 30 # effective wait + assert warning_args[11] == "" # 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"}] + assert warning_args[12] == [{"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.wait_for_function.side_effect = [ + None, + PlaywrightTimeout("timed out"), + ] mock_page.evaluate.side_effect = [ {"height": 2000, "top": 0, "left": 0, "width": 800}, None, [{"chartId": "7", "state": "nothing_mounted"}], + [{"chartId": "7", "state": "nothing_mounted"}], ] with patch("superset.utils.screenshot_utils.logger") as mock_logger: @@ -484,7 +554,7 @@ def test_timeout_warning_includes_log_context(self, mock_page): ) warning_args = mock_logger.warning.call_args[0] - assert warning_args[6] == " [execution_id=abc-123]" + assert warning_args[11] == " [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). @@ -502,6 +572,8 @@ def fake_wait_for_function(js, timeout=None): # 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 + if "getBoundingClientRect" not in js: + return None raise PlaywrightTimeout("Timeout waiting for chart holders") mock_page.wait_for_function.side_effect = fake_wait_for_function @@ -509,6 +581,7 @@ def fake_wait_for_function(js, timeout=None): {"height": 2000, "top": 0, "left": 0, "width": 800}, # dimensions None, # window.scrollTo(...) for tile 1 [{"chartId": "7", "state": "nothing_mounted"}], # diagnostics + [{"chartId": "7", "state": "nothing_mounted"}], # all states ] with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): @@ -517,7 +590,7 @@ def fake_wait_for_function(js, timeout=None): mock_page, "dashboard", tile_height=2000, load_wait=5 ) - assert js_call_count["n"] == 1 + assert js_call_count["n"] == 2 mock_page.screenshot.assert_not_called() def test_unready_holder_state_classification_embedded_in_js(self, mock_page): @@ -543,6 +616,7 @@ def test_unready_holder_state_classification_embedded_in_js(self, mock_page): '.dashboard-component-chart-holder[class*="dashboard-chart-id-"]' ) in js assert "holder.className.match(/\\bdashboard-chart-id-(\\d+)\\b/)" in js + assert "holders.length > 0" in CHART_HOLDERS_READY_JS assert "rendered" in FIND_CHART_HOLDER_STATES_JS assert "empty" in FIND_CHART_HOLDER_STATES_JS @@ -608,7 +682,7 @@ def test_all_chart_holders_ready_passes(self, mock_page): # 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.wait_for_function.call_count == 4 assert mock_page.screenshot.call_count == 3 assert result is not None diff --git a/tests/unit_tests/utils/webdriver_test.py b/tests/unit_tests/utils/webdriver_test.py index a7dea405b8e5..4c621f512541 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -770,16 +770,12 @@ def test_spinner_timeout_logs_warning_and_raises( assert exc_info.value is timeout mock_logger.error.assert_not_called() warning_call = mock_logger.warning.call_args - # Positional args are (format_string, count, url, load_wait, - # context_suffix, unready_chart_holders) -- assert against each - # argument's exact position rather than `x in warning_call.args`, - # which is tuple-element membership, not substring matching, but - # reads ambiguously enough that CodeQL flags it as if it were. - assert "Timed out waiting for" in warning_call.args[0] - assert warning_call.args[1] == 1 - assert warning_call.args[2] == "http://example.com" - assert warning_call.args[3] == 60 - assert warning_call.args[6] == [{"chartId": "42", "state": "nothing_mounted"}] + assert "terminal_reason=readiness_timeout" in warning_call.args[0] + assert warning_call.args[1] == "http://example.com" + assert warning_call.args[3] == 1 # mounted holders + assert warning_call.args[4] == 0 # ready holders + assert warning_call.args[7] == 60 + assert warning_call.args[9] == [{"chartId": "42", "state": "nothing_mounted"}] @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -930,10 +926,12 @@ def evaluate_side_effect(script): @patch("superset.utils.webdriver._browser_manager") @patch("superset.utils.webdriver.logger") @patch("superset.utils.webdriver.take_tiled_screenshot") - def test_tiled_screenshot_failure_falls_back_to_standard_screenshot( + def test_tiled_screenshot_failure_raises_without_unguarded_fallback( self, mock_take_tiled, mock_logger, mock_browser_manager ) -> None: - """When take_tiled_screenshot returns None, fall back to standard screenshot.""" + """A failed tiled capture must not fall back to a raw screenshot.""" + from superset.utils.webdriver import PlaywrightTimeout + mock_user = MagicMock() mock_user.username = "test_user" @@ -983,14 +981,16 @@ def evaluate_side_effect(script): mock_auth.return_value = mock_context driver = WebDriverPlaywright("chrome") - result = driver.get_screenshot( - "http://example.com", "standalone", mock_user - ) + with pytest.raises(PlaywrightTimeout): + driver.get_screenshot("http://example.com", "standalone", mock_user) - assert result == b"fallback_screenshot" mock_take_tiled.assert_called_once() + mock_page.screenshot.assert_not_called() mock_logger.warning.assert_any_call( - ("Tiled screenshot failed, falling back to standard screenshot"), + "Tiled screenshot failed for url %s%s and no safe " + "fallback exists; terminal_reason=tiled_capture_failed", + "http://example.com", + "", ) @@ -1096,8 +1096,11 @@ def test_all_chart_holders_ready_passes(self, mock_app, mock_browser_manager): assert result == b"screenshot" # Readiness diagnostics are emitted before polling so a task killed by # an outer limit still leaves useful state in the logs. - mock_page.evaluate.assert_called_once() - assert "state: 'rendered'" in mock_page.evaluate.call_args.args[0] + assert mock_page.evaluate.call_count == 2 + assert all( + "state: 'rendered'" in call.args[0] + for call in mock_page.evaluate.call_args_list + ) @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -1132,22 +1135,30 @@ def test_chart_capture_uses_positive_terminal_state_predicate( @patch("superset.utils.webdriver._browser_manager") @patch("superset.utils.webdriver.logger") @patch("superset.utils.webdriver.app") - def test_standalone_zero_holders_warns_before_polling( + def test_standalone_zero_holders_remain_not_ready_and_skip_capture( self, mock_app, mock_logger, mock_browser_manager ): + from superset.utils.webdriver import PlaywrightTimeout + mock_app.config = {**self._base_config} mock_context, mock_page = self._make_pw_mocks(mock_browser_manager) mock_page.evaluate.return_value = [] + mock_page.wait_for_function.side_effect = PlaywrightTimeout("zero holders") with patch.object(WebDriverPlaywright, "auth", return_value=mock_context): - WebDriverPlaywright("chrome").get_screenshot( - "http://example.com", "standalone", MagicMock() - ) + with pytest.raises(PlaywrightTimeout): + WebDriverPlaywright("chrome").get_screenshot( + "http://example.com", "standalone", MagicMock() + ) - mock_logger.warning.assert_any_call( - "dashboard capture proceeding with zero chart holders — " - "readiness gate inactive" + assert any( + "report_readiness_waiting_for_mount" in call.args[0] + for call in mock_logger.info.call_args_list + ) + assert ( + "terminal_reason=readiness_timeout" in mock_logger.warning.call_args.args[0] ) + mock_page.screenshot.assert_not_called() @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -1215,9 +1226,7 @@ def test_log_context_threaded_into_readiness_wait( log_context="execution_id=abc-123", ) - # context_suffix is the 6th positional arg (index 5); assert its - # exact value rather than tuple-element membership via `in`. - assert mock_logger.warning.call_args.args[5] == " [execution_id=abc-123]" + assert mock_logger.warning.call_args.args[8] == " [execution_id=abc-123]" @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -1252,6 +1261,81 @@ def test_wait_is_capped_to_remaining_runtime_task_budget( assert mock_page.wait_for_function.call_args.kwargs["timeout"] == 230_000 + def test_report_readiness_uses_shared_deadline_and_phase_reserves(self): + from uuid import UUID + + from superset.utils.report_execution import ( + ReportExecutionContext, + ReportExecutionDeadline, + ) + + page = MagicMock() + page.evaluate.return_value = [{"chartId": "7", "state": "rendered"}] + deadline = ReportExecutionDeadline( + total_seconds=900, + started_at=0, + _clock=lambda: 100, + ) + report_context = ReportExecutionContext( + execution_id=UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + report_schedule_id=11, + dashboard_id=805, + expected_chart_count=52, + deadline=deadline, + capture_reserve_seconds=60, + delivery_reserve_seconds=120, + cleanup_reserve_seconds=30, + ) + + WebDriverPlaywright._wait_for_charts_ready( + page, + "http://example.com/dashboard/805", + 5, + "standalone", + report_execution_context=report_context, + ) + + assert page.wait_for_function.call_args.kwargs["timeout"] == 590_000 + + def test_report_readiness_budget_exhaustion_skips_poll_and_capture(self): + from uuid import UUID + + from superset.utils.report_execution import ( + ReportExecutionBudgetExceededError, + ReportExecutionContext, + ReportExecutionDeadline, + ) + + page = MagicMock() + page.evaluate.return_value = [] + deadline = ReportExecutionDeadline( + total_seconds=900, + started_at=0, + _clock=lambda: 700, + ) + report_context = ReportExecutionContext( + execution_id=UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + report_schedule_id=11, + dashboard_id=805, + expected_chart_count=52, + deadline=deadline, + capture_reserve_seconds=60, + delivery_reserve_seconds=120, + cleanup_reserve_seconds=30, + ) + + with pytest.raises(ReportExecutionBudgetExceededError): + WebDriverPlaywright._wait_for_charts_ready( + page, + "http://example.com/dashboard/805", + 600, + "standalone", + report_execution_context=report_context, + ) + + page.wait_for_function.assert_not_called() + page.screenshot.assert_not_called() + def test_zero_load_wait_without_task_budget_preserves_playwright_no_timeout(self): page = MagicMock() page.evaluate.return_value = [] @@ -1332,12 +1416,6 @@ def test_unready_diagnostics_logged_early_and_at_failure( with pytest.raises(PlaywrightTimeout): driver.get_screenshot("http://example.com", "test-element", mock_user) - mock_logger.debug.assert_any_call( - "Chart holder states before readiness polling at url %s%s: %s", - "http://example.com", - "", - diagnostics, - ) mock_logger.info.assert_any_call( "Chart holders not ready before polling at url %s%s: %s", "http://example.com", @@ -1345,8 +1423,8 @@ def test_unready_diagnostics_logged_early_and_at_failure( diagnostics, ) failure_args = mock_logger.warning.call_args.args - assert failure_args[6] == diagnostics - assert failure_args[7] == diagnostics + assert failure_args[9] == diagnostics + assert failure_args[10] == diagnostics mock_page.locator.return_value.screenshot.assert_not_called() @@ -1414,9 +1492,9 @@ def record_wait_for_timeout(ms): assert "animation_wait" in call_order spinner_idx = call_order.index("spinner_wait") anim_idx = call_order.index("animation_wait") - assert spinner_idx < anim_idx, ( - "spinner wait must precede animation wait in non-tiled path" - ) + assert ( + spinner_idx < anim_idx + ), "spinner wait must precede animation wait in non-tiled path" @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -1438,7 +1516,7 @@ def test_animation_wait_after_spinner_wait_tiled_enabled_small_dashboard( mock_context, mock_page = self._make_pw_mocks(mock_browser_manager) # Small dashboard: 3 charts, 1000px height — below both thresholds - mock_page.evaluate.side_effect = [3, 1000, []] + mock_page.evaluate.side_effect = [3, 1000, [], []] call_order: list[str] = [] @@ -1498,6 +1576,8 @@ def test_tiled_path_passes_animation_wait_per_tile_no_global_wait( load_wait=30, animation_wait=2, log_context=None, + report_execution_context=None, + url="http://example.com", ) # 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) @@ -1506,18 +1586,20 @@ def test_tiled_path_passes_animation_wait_per_tile_no_global_wait( for call in mock_page.wait_for_timeout.call_args_list if call[0][0] == 2 * 1000 ] - assert animation_waits == [], ( - "No global 2s animation wait_for_timeout should fire on the tiled path" - ) + assert ( + animation_waits == [] + ), "No global 2s animation wait_for_timeout should fire on the tiled path" @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @patch("superset.utils.webdriver.take_tiled_screenshot") @patch("superset.utils.webdriver.app") - def test_tiled_fallback_triggered_on_empty_bytes( + def test_tiled_empty_bytes_raise_without_unguarded_fallback( self, mock_app, mock_take_tiled, mock_browser_manager ): - """Tiled fallback fires when take_tiled_screenshot returns b"" (not None).""" + """Empty tiled output fails instead of invoking raw full-page capture.""" + from superset.utils.webdriver import PlaywrightTimeout + mock_user = MagicMock() mock_user.username = "test_user" mock_app.config = { @@ -1537,15 +1619,14 @@ def test_tiled_fallback_triggered_on_empty_bytes( mock_page.screenshot.return_value = b"fallback" with patch.object(WebDriverPlaywright, "auth", return_value=mock_context): - result = WebDriverPlaywright("chrome").get_screenshot( - "http://example.com", "standalone", mock_user - ) + with pytest.raises(PlaywrightTimeout): + WebDriverPlaywright("chrome").get_screenshot( + "http://example.com", "standalone", mock_user + ) - assert result == b"fallback" # Tiled path was taken (take_tiled_screenshot was called) mock_take_tiled.assert_called_once() - # Standard screenshot was called as fallback (full_page=True for "standalone") - mock_page.screenshot.assert_called_with(full_page=True) + mock_page.screenshot.assert_not_called() @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -1571,6 +1652,6 @@ def test_animation_wait_skipped_when_zero(self, mock_app, mock_browser_manager): timeout_values = [ call[0][0] for call in mock_page.wait_for_timeout.call_args_list ] - assert timeout_values == [0], ( - f"Expected only [0] (headstart), got {timeout_values}" - ) + assert timeout_values == [ + 0 + ], f"Expected only [0] (headstart), got {timeout_values}" From 163057e73d095d3004853b466d71ffc4fd31f21f Mon Sep 17 00:00:00 2001 From: Mafi Date: Thu, 30 Jul 2026 23:42:12 +0000 Subject: [PATCH 02/19] fix(reports): narrow recovery and capture compatibility --- .../configuration/alerts-reports.mdx | 12 +- superset/commands/report/execute.py | 220 +++++++----------- superset/config.py | 9 +- superset/tasks/scheduler.py | 41 +--- superset/utils/report_execution.py | 27 +++ superset/utils/screenshot_utils.py | 105 +++++---- superset/utils/webdriver.py | 148 +++++++----- .../reports/commands_tests.py | 6 +- .../reports/scheduler_tests.py | 25 -- .../commands/report/execute_test.py | 140 ++++++----- .../unit_tests/utils/test_report_execution.py | 19 ++ .../unit_tests/utils/test_screenshot_utils.py | 90 ++++++- tests/unit_tests/utils/webdriver_test.py | 146 ++++++++++-- 13 files changed, 584 insertions(+), 404 deletions(-) diff --git a/docs/admin_docs/configuration/alerts-reports.mdx b/docs/admin_docs/configuration/alerts-reports.mdx index 462853bb5a51..2eee8fd16e97 100644 --- a/docs/admin_docs/configuration/alerts-reports.mdx +++ b/docs/admin_docs/configuration/alerts-reports.mdx @@ -249,21 +249,23 @@ CELERY_CONFIG = CeleryConfig # this only when the complete report pipeline is expected to take longer. ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = 900 -# These reserves are part of (not additions to) the total budget. Readiness -# polling stops in time to leave capacity for the later phases. +# These reserves are part of (not additions to) the total budget and their sum +# must be less than it. Readiness polling stops in time to leave capacity for +# the later phases. ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS = 60 ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS = 120 ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS = 30 # Celery's hard limit leaves this additional window for terminal cleanup after -# the 15-minute soft limit. +# the 15-minute soft limit. ALERT_REPORTS_WORKING_TIME_OUT_KILL controls these +# Celery limits; disabling it does not disable the application deadline above. ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS = 30 # Screenshot-specific waits continue to apply to thumbnails and other # standalone screenshot calls. Scheduled reports derive their waits from the # shared execution deadline above. -SCREENSHOT_LOCATE_WAIT = 10 -SCREENSHOT_LOAD_WAIT = 60 +SCREENSHOT_LOCATE_WAIT = 100 +SCREENSHOT_LOAD_WAIT = 600 # Slack configuration SLACK_API_TOKEN = "xoxb-" diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 45942f21d5ea..d46e42d80627 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -38,9 +38,7 @@ ReportScheduleAlertGracePeriodError, ReportScheduleClientErrorsException, ReportScheduleCsvFailedError, - ReportScheduleCsvTimeout, ReportScheduleDataFrameFailedError, - ReportScheduleDataFrameTimeout, ReportScheduleExecuteUnexpectedError, ReportScheduleExecutorNotFoundError, ReportScheduleNotFoundError, @@ -54,7 +52,6 @@ ReportScheduleUnexpectedError, ReportScheduleWorkingTimeoutError, ReportScheduleXlsxFailedError, - ReportScheduleXlsxTimeout, ) from superset.common.chart_data import ChartDataResultFormat, ChartDataResultType from superset.daos.report import ( @@ -91,6 +88,7 @@ from superset.utils.file import sanitize_title from superset.utils.pdf import build_pdf_from_screenshots from superset.utils.report_execution import ( + ReportExecutionBudgetExceededError, ReportExecutionContext, ReportExecutionDeadline, ) @@ -128,68 +126,32 @@ def resolve_executor_user(model: ReportSchedule) -> tuple["User", str]: return user, username -def mark_report_execution_terminal_error( - report_schedule_id: int, - execution_id: UUID, - terminal_reason: str, -) -> bool: - """Idempotently terminate the WORKING row owned by a failed Celery task.""" - - try: - working_log = ( - db.session.query(ReportExecutionLog) - .filter( - ReportExecutionLog.report_schedule_id == report_schedule_id, - ReportExecutionLog.uuid == execution_id, - ReportExecutionLog.state == ReportState.WORKING, - ReportExecutionLog.error_message.is_(None), - ) - .first() +def log_report_delivery_phase( + report_context: ReportExecutionContext | None, + recipient_type: ReportRecipientType | None, + phase: str, + *, + enforce_budget: bool, +) -> None: + """Enforce and log a notification phase when executing a report.""" + + if report_context is None: + return + deadline = report_context.deadline + if enforce_budget: + deadline.timeout_seconds( + "notification_delivery", + reserve_seconds=report_context.cleanup_reserve_seconds, ) - if working_log is None: - return False - - latest_working_log = ( - db.session.query(ReportExecutionLog) - .filter( - ReportExecutionLog.report_schedule_id == report_schedule_id, - ReportExecutionLog.state == ReportState.WORKING, - ReportExecutionLog.error_message.is_(None), - ) - .order_by(ReportExecutionLog.end_dttm.desc()) - .first() - ) - report_schedule = working_log.report_schedule - owns_schedule_state = ( - report_schedule.last_state == ReportState.WORKING - and latest_working_log is not None - and latest_working_log.uuid == execution_id - ) - ended_at = datetime.now(timezone.utc).replace(tzinfo=None) - working_log.state = ReportState.ERROR - working_log.error_message = terminal_reason - working_log.end_dttm = ended_at - if owns_schedule_state: - report_schedule.last_state = ReportState.ERROR - report_schedule.last_eval_dttm = ended_at - - db.session.commit() # pylint: disable=consider-using-transaction - logger.warning( - "report_execution_terminal capture_kind=report execution_id=%s " - "report_schedule_id=%s " - "dashboard_id=%s chart_id=%s state=%s terminal_reason=%s " - "elapsed_seconds=unknown remaining_seconds=unknown", - execution_id, - report_schedule_id, - report_schedule.dashboard_id, - report_schedule.chart_id, - ReportState.ERROR.value, - terminal_reason, - ) - return True - except Exception: - db.session.rollback() # pylint: disable=consider-using-transaction - raise + logger.info( + "report_delivery_%s %s recipient_type=%s elapsed_seconds=%.2f " + "remaining_seconds=%.2f", + phase, + report_context.log_context, + recipient_type, + deadline.elapsed_seconds, + deadline.remaining_seconds, + ) class BaseReportState: @@ -725,7 +687,7 @@ def _get_screenshots(self) -> list[bytes]: ), len(imges), ) - except SoftTimeLimitExceeded as ex: + except SoftTimeLimitExceeded: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() @@ -740,7 +702,9 @@ def _get_screenshots(self) -> list[bytes]: else None ), ) - raise ReportScheduleScreenshotTimeout() from ex + raise + except ReportExecutionBudgetExceededError: + raise except Exception as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time @@ -903,18 +867,15 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: f"Unsupported chart data result format: {result_format}" ) - timeout_error: type[CommandException] failed_error: type[CommandException] if result_format == ChartDataResultFormat.XLSX: - label, timeout_error, failed_error = ( + label, failed_error = ( "Excel", - ReportScheduleXlsxTimeout, ReportScheduleXlsxFailedError, ) else: - label, timeout_error, failed_error = ( + label, failed_error = ( "CSV", - ReportScheduleCsvTimeout, ReportScheduleCsvFailedError, ) @@ -975,7 +936,7 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: elapsed_seconds, self._execution_id, ) - except SoftTimeLimitExceeded as ex: + except SoftTimeLimitExceeded: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() @@ -985,7 +946,9 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: elapsed_seconds, self._execution_id, ) - raise timeout_error() from ex + raise + except ReportExecutionBudgetExceededError: + raise except Exception as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time @@ -1039,7 +1002,7 @@ def _get_embedded_data(self) -> pd.DataFrame: elapsed_seconds, self._execution_id, ) - except SoftTimeLimitExceeded as ex: + except SoftTimeLimitExceeded: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() @@ -1048,7 +1011,9 @@ def _get_embedded_data(self) -> pd.DataFrame: elapsed_seconds, self._execution_id, ) - raise ReportScheduleDataFrameTimeout() from ex + raise + except ReportExecutionBudgetExceededError: + raise except Exception as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time @@ -1220,27 +1185,16 @@ def _send( :raises: CommandException """ notification_errors: list[SupersetError] = [] + report_context = getattr(self, "_report_execution_context", None) for recipient in recipients: notification = create_notification(recipient, notification_content) try: try: - cleanup_reserve = ( - self._report_execution_context.cleanup_reserve_seconds - if self._report_execution_context - else 0.0 - ) - self._phase_timeout( - "notification_delivery", - reserve_seconds=cleanup_reserve, - ) - elapsed, remaining = self._budget_values() - logger.info( - "report_delivery_start %s recipient_type=%s " - "elapsed_seconds=%s remaining_seconds=%s", - self._log_context, - recipient.type, - f"{elapsed:.2f}" if elapsed is not None else None, - f"{remaining:.2f}" if remaining is not None else None, + log_report_delivery_phase( + report_context, + getattr(recipient, "type", None), + "start", + enforce_budget=True, ) if app.config["ALERT_REPORTS_NOTIFICATION_DRY_RUN"]: logger.info( @@ -1252,14 +1206,11 @@ def _send( ) else: notification.send() - elapsed, remaining = self._budget_values() - logger.info( - "report_delivery_complete %s recipient_type=%s " - "elapsed_seconds=%s remaining_seconds=%s", - self._log_context, - recipient.type, - f"{elapsed:.2f}" if elapsed is not None else None, - f"{remaining:.2f}" if remaining is not None else None, + log_report_delivery_phase( + report_context, + getattr(recipient, "type", None), + "complete", + enforce_budget=False, ) except SlackV1NotificationError as ex: # The slack notification should be sent with the v2 api @@ -1269,13 +1220,11 @@ def _send( self.update_report_schedule_slack_v2() recipient.type = ReportRecipientType.SLACKV2 notification = create_notification(recipient, notification_content) - self._phase_timeout( - "notification_delivery", - reserve_seconds=( - self._report_execution_context.cleanup_reserve_seconds - if self._report_execution_context - else 0.0 - ), + log_report_delivery_phase( + report_context, + recipient.type, + "retry", + enforce_budget=True, ) notification.send() except ( @@ -1437,12 +1386,18 @@ def next(self) -> None: # noqa: C901 except SoftTimeLimitExceeded: # Persist the terminal state inside the cleanup grace period rather # than spending it on an error notification. The task-level handler - # is a second, idempotent safety net for failures outside this state. + # then reports the Celery task failure without performing DB work. self.update_report_schedule_and_log( ReportState.ERROR, error_message="celery_soft_timeout", ) raise + except ReportExecutionBudgetExceededError as ex: + self.update_report_schedule_and_log( + ReportState.ERROR, + error_message=f"report_execution_budget_exhausted:{ex.phase}", + ) + raise except (SupersetErrorsException, Exception) as first_ex: error_message = str(first_ex) if isinstance(first_ex, SupersetErrorsException): @@ -1530,36 +1485,31 @@ def next(self) -> None: self._execution_id, ) exception_timeout = ReportScheduleWorkingTimeoutError() - stale_execution_id = last_working.uuid if last_working else None - if stale_execution_id is not None: - mark_report_execution_terminal_error( - self._report_schedule.id, - stale_execution_id, - "working_timeout_recovery", - ) - if ( - self._report_schedule.type == ReportScheduleType.REPORT - and stale_execution_id != self._execution_id - ): + if last_working and last_working.uuid != self._execution_id: + # This invocation is the first application-owned opportunity to + # recover a worker-lost execution. Terminalize the stale row in + # the same session as the recovery invocation's ERROR row; the + # create_log() commit below persists both changes together. + last_working.state = ReportState.ERROR + last_working.error_message = str(exception_timeout) + last_working.end_dttm = datetime.now(timezone.utc).replace(tzinfo=None) logger.info( - "report_execution_recovered %s stale_execution_id=%s " - "terminal_reason=working_timeout_recovery; " - "proceeding with new scheduled execution", + "report_execution_terminal %s lost_execution_id=%s " + "state=%s terminal_reason=working_timeout_recovered", self._log_context, - stale_execution_id, - ) - ReportNotTriggeredErrorState( - self._report_schedule, - self._scheduled_dttm, - self._execution_id, - self._report_execution_context, - ).next() - return - if stale_execution_id != self._execution_id: - self.update_report_schedule_and_log( - ReportState.ERROR, - error_message=str(exception_timeout), + last_working.uuid, + ReportState.ERROR.value, ) + # Keep the established state-machine recovery transaction: the + # recovery invocation records ERROR and stops. If it reuses the + # original execution id, create_log promotes that exact WORKING row; + # a distinct id terminalizes the lost row and records its own ERROR + # without risking an uncertain duplicate delivery after worker loss. + # The following schedule can start from ERROR normally. + self.update_report_schedule_and_log( + ReportState.ERROR, + error_message=str(exception_timeout), + ) raise exception_timeout logger.warning( "Report still in working state, refusing to re-compute - execution_id: %s", diff --git a/superset/config.py b/superset/config.py index 2d0808bbcb1a..36b5de5c3ff0 100644 --- a/superset/config.py +++ b/superset/config.py @@ -2451,7 +2451,8 @@ def EMAIL_HEADER_MUTATOR( # pylint: disable=invalid-name,unused-argument # noq ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = int(timedelta(minutes=15).total_seconds()) # Capacity inside the execution budget reserved from chart-readiness polling # for image capture/PDF construction, notification delivery, and the terminal -# execution-log transition, respectively. Unused capacity flows to later phases. +# execution-log transition, respectively. Their sum must be less than the total; +# unused capacity flows to later phases. ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS = int( timedelta(minutes=1).total_seconds() ) @@ -2461,8 +2462,10 @@ def EMAIL_HEADER_MUTATOR( # pylint: disable=invalid-name,unused-argument # noq ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS = int( timedelta(seconds=30).total_seconds() ) -# Celery raises the soft timeout at the execution deadline. The hard timeout -# leaves this additional window for the soft-timeout handler to persist ERROR. +# Celery raises the soft timeout at the execution deadline when +# ALERT_REPORTS_WORKING_TIME_OUT_KILL is enabled. The application deadline is +# enforced independently. The hard timeout leaves this additional window for +# the soft-timeout handler to persist ERROR. ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS = int( timedelta(seconds=30).total_seconds() ) diff --git a/superset/tasks/scheduler.py b/superset/tasks/scheduler.py index 7d1147dbdfc9..8a24180ebe28 100644 --- a/superset/tasks/scheduler.py +++ b/superset/tasks/scheduler.py @@ -31,10 +31,7 @@ from superset.commands.exceptions import CommandException from superset.commands.logs.prune import LogPruneCommand from superset.commands.report.exceptions import ReportScheduleUnexpectedError -from superset.commands.report.execute import ( - AsyncExecuteReportScheduleCommand, - mark_report_execution_terminal_error, -) +from superset.commands.report.execute import AsyncExecuteReportScheduleCommand from superset.commands.report.log_prune import AsyncPruneReportScheduleLogCommand from superset.commands.sql_lab.query import QueryPruneCommand from superset.commands.tasks.prune import TaskPruneCommand @@ -70,27 +67,6 @@ def log_task_failure( # pylint: disable=unused-argument ) -> None: task_name = sender.name if sender else "Unknown" logger.exception("Celery task %s failed: %s", task_name, exception, exc_info=einfo) - if task_name != "reports.execute" or task_id is None or not args: - return - try: - execution_id = UUID(task_id) - report_schedule_id = int(args[0]) - exception_name = type(exception).__name__ if exception else "UnknownError" - terminal_reason = f"celery_task_failure:{exception_name}" - mark_report_execution_terminal_error( - report_schedule_id, - execution_id, - terminal_reason, - ) - except Exception: - # Celery signal handlers must not mask the original task failure. - logger.exception( - "Failed terminal cleanup for report task capture_kind=report " - "execution_id=%s " - "report_schedule_id=%s terminal_reason=cleanup_hook_failed", - task_id, - args[0], - ) @celery_app.task( @@ -156,31 +132,18 @@ def execute(self: Task, report_schedule_id: int) -> None: ).run() except SoftTimeLimitExceeded: logger.warning( - "Report execution hit Celery soft timeout; capture_kind=report " - "execution_id=%s " + "Alert/report execution hit Celery soft timeout; execution_id=%s " "report_schedule_id=%s terminal_reason=celery_soft_timeout", task_id, report_schedule_id, exc_info=True, ) - if task_id: - mark_report_execution_terminal_error( - report_schedule_id, - UUID(task_id), - "celery_soft_timeout", - ) self.update_state(state="FAILURE") raise except ReportScheduleUnexpectedError: logger.exception( "An unexpected error occurred while executing the report: %s", task_id ) - if task_id: - mark_report_execution_terminal_error( - report_schedule_id, - UUID(task_id), - "unexpected_execution_error", - ) self.update_state(state="FAILURE") except CommandException as ex: logger_func, level = get_logger_from_status(ex.status) diff --git a/superset/utils/report_execution.py b/superset/utils/report_execution.py index c402829e6a5d..c3e0e63c0249 100644 --- a/superset/utils/report_execution.py +++ b/superset/utils/report_execution.py @@ -56,6 +56,12 @@ class ReportExecutionDeadline: compare=False, ) + def __post_init__(self) -> None: + """Reject deadlines that cannot provide any execution time.""" + + if self.total_seconds <= 0: + raise ValueError("Report execution budget must be greater than zero") + @property def elapsed_seconds(self) -> float: """Return non-negative wall-clock time consumed by this execution.""" @@ -113,6 +119,22 @@ class ReportExecutionContext: delivery_reserve_seconds: float = 0.0 cleanup_reserve_seconds: float = 0.0 + def __post_init__(self) -> None: + """Validate that configured phase reserves fit inside the deadline.""" + + reserves = ( + self.capture_reserve_seconds, + self.delivery_reserve_seconds, + self.cleanup_reserve_seconds, + ) + if any(reserve < 0 for reserve in reserves): + raise ValueError("Report execution phase reserves cannot be negative") + if sum(reserves) >= self.deadline.total_seconds: + raise ValueError( + "Report execution phase reserves must total less than the " + "execution budget" + ) + @property def log_context(self) -> str: """Return stable key/value identifiers for plain-text log formatters.""" @@ -154,6 +176,11 @@ def get_report_task_timeout_options( if is_report: budget = int(config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"]) hard_grace = int(config["ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS"]) + if budget <= 0 or hard_grace < 0: + raise ValueError( + "Report execution budget must be positive and hard-timeout " + "grace cannot be negative" + ) return { "soft_time_limit": budget, "time_limit": budget + hard_grace, diff --git a/superset/utils/screenshot_utils.py b/superset/utils/screenshot_utils.py index 2883d23d657a..793ce44b63ef 100644 --- a/superset/utils/screenshot_utils.py +++ b/superset/utils/screenshot_utils.py @@ -198,6 +198,9 @@ def resolve_screenshot_task_budget_seconds( """ CHART_HOLDERS_READY_JS = ( + f"() => {{ {UNREADY_CHART_HOLDERS_JS_BODY} return unready.length === 0; }}" +) +REPORT_CHART_HOLDERS_READY_JS = ( f"() => {{ {UNREADY_CHART_HOLDERS_JS_BODY} " "return holders.length > 0 && unready.length === 0; }" ) @@ -220,7 +223,11 @@ def resolve_screenshot_task_budget_seconds( """ -def combine_screenshot_tiles(screenshot_tiles: list[bytes]) -> bytes: +def combine_screenshot_tiles( + screenshot_tiles: list[bytes], + *, + allow_partial_fallback: bool = True, +) -> bytes: """ Combine multiple screenshot tiles into a single vertical image. @@ -260,8 +267,11 @@ def combine_screenshot_tiles(screenshot_tiles: list[bytes]) -> bytes: except Exception as e: logger.exception("Failed to combine screenshot tiles: %s", e) - # Return the first tile as fallback - return screenshot_tiles[0] + if allow_partial_fallback: + # Preserve the historical thumbnail behavior. Scheduled reports + # opt out because delivering only the first tile is incomplete. + return screenshot_tiles[0] + raise def take_tiled_screenshot( # noqa: C901 @@ -361,44 +371,36 @@ def _timeout_seconds( * 1000 ) - mount_wait = _timeout_seconds( - "chart_holder_mount", - requested_seconds=None if report_execution_context else load_wait, - reserve_seconds=( - report_execution_context.readiness_reserve_seconds - if report_execution_context - else 0.0 - ), - ) - try: - page.wait_for_function( - CHART_HOLDERS_MOUNTED_JS, - timeout=mount_wait * 1000, - ) - except PlaywrightTimeout: - holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) - elapsed, remaining = _deadline_values() - logger.warning( - "report_readiness_terminal url=%s expected_holders=%s " - "mounted_holders=%s ready_holders=0 elapsed_seconds=%.2f " - "remaining_seconds=%s effective_wait_seconds=%.2f%s " - "terminal_reason=zero_holders_timeout states=%s; " - "aborting before dimensions, capture, or delivery", - url, - ( - report_execution_context.expected_chart_count - if report_execution_context - else None - ), - len(holder_states), - elapsed, - f"{remaining:.2f}" if remaining is not None else None, - mount_wait, - context_suffix, - holder_states, + if report_execution_context: + mount_wait = _timeout_seconds( + "chart_holder_mount", + reserve_seconds=report_execution_context.readiness_reserve_seconds, ) - readiness_timeout = True - raise + try: + page.wait_for_function( + CHART_HOLDERS_MOUNTED_JS, + timeout=mount_wait * 1000, + ) + except PlaywrightTimeout: + holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) + elapsed, remaining = _deadline_values() + logger.warning( + "report_readiness_terminal url=%s expected_holders=%s " + "mounted_holders=%s ready_holders=0 elapsed_seconds=%.2f " + "remaining_seconds=%s effective_wait_seconds=%.2f%s " + "terminal_reason=zero_holders_timeout states=%s; " + "aborting before dimensions, capture, or delivery", + url, + report_execution_context.expected_chart_count, + len(holder_states), + elapsed, + f"{remaining:.2f}" if remaining is not None else None, + mount_wait, + context_suffix, + holder_states, + ) + readiness_timeout = True + raise # Get dashboard dimensions and position element_info = page.evaluate(f"""() => {{ @@ -459,7 +461,11 @@ def _timeout_seconds( ) try: page.wait_for_function( - CHART_HOLDERS_READY_JS, + ( + REPORT_CHART_HOLDERS_READY_JS + if report_execution_context + else CHART_HOLDERS_READY_JS + ), timeout=tile_load_wait * 1000, ) except PlaywrightTimeout: @@ -598,8 +604,16 @@ def _timeout_seconds( logger.debug("Captured tile %s/%s with clip %s", i + 1, num_tiles, clip) # Combine all tiles - holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) - if not isinstance(holder_states, list): + try: + holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) + if not isinstance(holder_states, list): + holder_states = [] + except Exception: # noqa: BLE001 # diagnostics must not discard valid tiles + logger.warning( + "Unable to collect final chart-holder diagnostics%s", + context_suffix, + exc_info=True, + ) holder_states = [] ready_states = {"rendered", "empty", "error", "virtualized"} elapsed, remaining = _deadline_values() @@ -619,7 +633,10 @@ def _timeout_seconds( context_suffix, ) logger.info("Combining screenshot tiles...") - combined_screenshot = combine_screenshot_tiles(screenshot_tiles) + combined_screenshot = combine_screenshot_tiles( + screenshot_tiles, + allow_partial_fallback=report_execution_context is None, + ) return combined_screenshot diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index acf01f0415a7..5ae3dcc4c65e 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -49,6 +49,7 @@ CHART_CONTAINER_READY_JS, CHART_HOLDERS_READY_JS, FIND_CHART_HOLDER_STATES_JS, + REPORT_CHART_HOLDERS_READY_JS, resolve_screenshot_task_budget_seconds, take_tiled_screenshot, ) @@ -442,11 +443,15 @@ def _wait_for_charts_ready( elapsed, context_suffix, ) - readiness_predicate = ( - CHART_CONTAINER_READY_JS - if element_name == "chart-container" - else CHART_HOLDERS_READY_JS - ) + if element_name == "chart-container": + readiness_predicate = CHART_CONTAINER_READY_JS + elif report_execution_context: + readiness_predicate = REPORT_CHART_HOLDERS_READY_JS + else: + # Preserve the thumbnail behavior introduced by #42253. The + # stricter zero-holder gate is report-specific because an empty + # dashboard thumbnail is still a valid cache artifact. + readiness_predicate = CHART_HOLDERS_READY_JS try: page.wait_for_function( readiness_predicate, @@ -735,15 +740,29 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n url=url, ) if not img: - logger.warning( - "Tiled screenshot failed for url %s%s and no safe " - "fallback exists; terminal_reason=tiled_capture_failed", - url, - f" [{log_context}]" if log_context else "", - ) - raise PlaywrightTimeout( - f"Tiled screenshot failed for url {url}" - ) + if report_execution_context is None: + logger.warning( + "Tiled screenshot failed for url %s%s; " + "preserving thumbnail fallback behavior", + url, + (f" [{log_context}]" if log_context else ""), + ) + img = WebDriverPlaywright._get_screenshot( + page, + element, + element_name, + ) + else: + logger.warning( + "Tiled screenshot failed for url %s%s and no safe " + "fallback exists; " + "terminal_reason=tiled_capture_failed", + url, + f" [{log_context}]" if log_context else "", + ) + raise PlaywrightTimeout( + f"Tiled screenshot failed for url {url}" + ) logger.debug( "Tiled screenshot result: %d bytes for url: %s", len(img) if img else 0, @@ -1218,41 +1237,46 @@ def phase_timeout( ) raise - if element_name == "standalone": + if report_execution_context and element_name in { + "standalone", + "chart-container", + }: + readiness_predicate = ( + REPORT_CHART_HOLDERS_READY_JS + if element_name == "standalone" + else CHART_CONTAINER_READY_JS + ) readiness_timeout = phase_timeout( "chart_readiness", - None if report_execution_context else self._screenshot_load_wait, - ( - report_execution_context.readiness_reserve_seconds - if report_execution_context - else 0.0 - ), + None, + report_execution_context.readiness_reserve_seconds, ) try: WebDriverWait(driver, readiness_timeout).until( lambda webdriver: webdriver.execute_script( - f"return ({CHART_HOLDERS_READY_JS})()" + f"return ({readiness_predicate})()" ) ) - holder_states = driver.execute_script( - f"return ({FIND_CHART_HOLDER_STATES_JS})()" + holder_states = ( + driver.execute_script( + f"return ({FIND_CHART_HOLDER_STATES_JS})()" + ) + if element_name == "standalone" + else [ + { + "chartId": report_execution_context.chart_id, + "state": "rendered", + } + ] ) ready_states = {"rendered", "empty", "error", "virtualized"} - deadline = ( - report_execution_context.deadline - if report_execution_context - else None - ) + deadline = report_execution_context.deadline logger.info( "report_readiness_ready url=%s expected_holders=%s " "mounted_holders=%s ready_holders=%s elapsed_seconds=%s " "remaining_seconds=%s%s", url, - ( - report_execution_context.expected_chart_count - if report_execution_context - else None - ), + report_execution_context.expected_chart_count, len(holder_states), sum( holder.get("state") in ready_states @@ -1263,18 +1287,23 @@ def phase_timeout( f" [{log_context}]" if log_context else "", ) except TimeoutException: - holder_states = driver.execute_script( - f"return ({FIND_CHART_HOLDER_STATES_JS})()" + holder_states = ( + driver.execute_script( + f"return ({FIND_CHART_HOLDER_STATES_JS})()" + ) + if element_name == "standalone" + else [ + { + "chartId": report_execution_context.chart_id, + "state": "not_ready", + } + ] ) ready_states = {"rendered", "empty", "error", "virtualized"} ready_holders = sum( holder.get("state") in ready_states for holder in holder_states ) - deadline = ( - report_execution_context.deadline - if report_execution_context - else None - ) + deadline = report_execution_context.deadline logger.warning( "report_readiness_terminal url=%s expected_holders=%s " "mounted_holders=%s ready_holders=%s elapsed_seconds=%s " @@ -1282,11 +1311,7 @@ def phase_timeout( "terminal_reason=readiness_timeout states=%s; " "aborting before capture or delivery", url, - ( - report_execution_context.expected_chart_count - if report_execution_context - else None - ), + report_execution_context.expected_chart_count, len(holder_states), ready_holders, (f"{deadline.elapsed_seconds:.2f}" if deadline else None), @@ -1317,12 +1342,31 @@ def phase_timeout( ) ) except TimeoutException: - logger.warning( - "Selenium timed out waiting for chart to draw at url %s", - url, - exc_info=True, - ) - raise + if element_name == "standalone": + logger.info("Timeout Exception caught") + # Preserve support for empty dashboard thumbnails. Report + # dashboards use the positive holder gate above instead. + try: + WebDriverWait(driver, 0).until( + EC.visibility_of_all_elements_located( + (By.CLASS_NAME, "grid-container") + ) + ) + except Exception: + logger.warning( + "Selenium timed out waiting for dashboard to draw " + "at url %s", + url, + exc_info=True, + ) + raise + else: + logger.warning( + "Selenium timed out waiting for chart to draw at url %s", + url, + exc_info=True, + ) + raise try: # charts took too long to load diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index 26afb651117a..ddbe19977d10 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -86,6 +86,7 @@ from superset.tasks.types import ExecutorType from superset.utils import json from superset.utils.database import get_example_database +from superset.utils.report_execution import ReportExecutionContext from tests.integration_tests.fixtures.birth_names_dashboard import ( load_birth_names_dashboard_with_slices, # noqa: F401 load_birth_names_data, # noqa: F401 @@ -877,7 +878,9 @@ def test_email_chart_report_schedule_alpha_owner( username = "" def _screenshot_side_effect( - user: User, log_context: Optional[str] = None + user: User, + log_context: Optional[str] = None, + report_execution_context: ReportExecutionContext | None = None, ) -> Optional[bytes]: nonlocal username username = user.username @@ -1951,6 +1954,7 @@ def test_report_schedule_working_timeout(create_report_slack_chart_working): assert ReportScheduleWorkingTimeoutError.message in [ log.error_message for log in logs ] + assert {log.state for log in logs} == {ReportState.ERROR} assert create_report_slack_chart_working.last_state == ReportState.ERROR diff --git a/tests/integration_tests/reports/scheduler_tests.py b/tests/integration_tests/reports/scheduler_tests.py index f8cccc1dc794..48b3df0e75bb 100644 --- a/tests/integration_tests/reports/scheduler_tests.py +++ b/tests/integration_tests/reports/scheduler_tests.py @@ -17,7 +17,6 @@ from random import randint from unittest.mock import MagicMock, patch -from uuid import UUID import pytest from freezegun import freeze_time @@ -272,27 +271,3 @@ def test_log_task_failure_without_sender(logger_mock): logger_mock.exception.assert_called_once_with( "Celery task %s failed: %s", "Unknown", mock_exception, exc_info=mock_einfo ) - - -@patch("superset.tasks.scheduler.mark_report_execution_terminal_error") -@patch("superset.tasks.scheduler.logger") -def test_log_task_failure_cleans_up_report_working_state( - logger_mock, - cleanup_mock, -): - task = MagicMock() - task.name = "reports.execute" - execution_id = "084e7ee6-5557-4ecd-9632-b7f39c9ec524" - - log_task_failure( - sender=task, - task_id=execution_id, - exception=RuntimeError("worker lost"), - args=(11,), - ) - - cleanup_mock.assert_called_once_with( - 11, - UUID(execution_id), - "celery_task_failure:RuntimeError", - ) diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index 0d7d654e538b..2687588ffb53 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -40,11 +40,9 @@ ReportScheduleUnexpectedError, ReportScheduleWorkingTimeoutError, ReportScheduleXlsxFailedError, - ReportScheduleXlsxTimeout, ) from superset.commands.report.execute import ( BaseReportState, - mark_report_execution_terminal_error, ReportNotTriggeredErrorState, ReportScheduleStateMachine, ReportSuccessState, @@ -1434,11 +1432,6 @@ def test_get_data_xlsx_fetches_chart_data( @pytest.mark.parametrize( ("side_effect", "expected_exception", "expected_message"), [ - ( - SoftTimeLimitExceeded(), - ReportScheduleXlsxTimeout, - "timeout occurred while generating an Excel file", - ), ( RuntimeError("export failed"), ReportScheduleXlsxFailedError, @@ -1671,14 +1664,10 @@ def test_get_content_raises_when_executor_user_missing( getattr(report_state, method_name)(*method_args) -def test_get_data_xlsx_wraps_soft_time_limit_as_xlsx_timeout( +def test_get_data_xlsx_propagates_celery_soft_time_limit( app: SupersetApp, mocker: MockerFixture ) -> None: - """ - A ``SoftTimeLimitExceeded`` during XLSX fetch surfaces as - ``ReportScheduleXlsxTimeout`` (not the CSV timeout class), so Excel report - timeouts are classified under the format-specific error. - """ + """Celery soft timeout must reach the state cleanup handler unchanged.""" from celery.exceptions import SoftTimeLimitExceeded app.config.update({"ALERT_REPORTS_CSV_REQUEST_TIMEOUT": 60}) @@ -1698,7 +1687,7 @@ def test_get_data_xlsx_wraps_soft_time_limit_as_xlsx_timeout( side_effect=SoftTimeLimitExceeded(), ) - with pytest.raises(ReportScheduleXlsxTimeout): + with pytest.raises(SoftTimeLimitExceeded): report_state._get_data(ChartDataResultFormat.XLSX) @@ -2261,10 +2250,6 @@ def test_working_state_timeout_raises_timeout_error(mocker: MockerFixture) -> No "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", return_value=mock_log, ) - cleanup = mocker.patch( - "superset.commands.report.execute.mark_report_execution_terminal_error", - return_value=True, - ) mocker.patch.object(state, "update_report_schedule_and_log") with pytest.raises(ReportScheduleWorkingTimeoutError): @@ -2274,11 +2259,6 @@ def test_working_state_timeout_raises_timeout_error(mocker: MockerFixture) -> No ReportState.ERROR, error_message=str(ReportScheduleWorkingTimeoutError()), ) - cleanup.assert_called_once_with( - state._report_schedule.id, - mock_log.uuid, - "working_timeout_recovery", - ) def test_working_state_still_working_raises_previous_working( @@ -2310,28 +2290,28 @@ def test_working_timeout_replay_promotes_original_execution_without_duplicate_lo mocker.patch.object(state, "is_on_working_timeout", return_value=True) working_log = mocker.Mock() working_log.uuid = state._execution_id + working_log.state = ReportState.WORKING working_log.end_dttm = datetime.utcnow() - timedelta(minutes=20) mocker.patch( "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", return_value=working_log, ) - cleanup = mocker.patch( - "superset.commands.report.execute.mark_report_execution_terminal_error", - return_value=True, - ) update = mocker.patch.object(state, "update_report_schedule_and_log") with pytest.raises(ReportScheduleWorkingTimeoutError): state.next() - cleanup.assert_called_once() - update.assert_not_called() + update.assert_called_once_with( + ReportState.ERROR, + error_message=str(ReportScheduleWorkingTimeoutError()), + ) + assert working_log.state == ReportState.WORKING -def test_new_report_execution_proceeds_after_stale_working_cleanup( +def test_new_report_execution_does_not_deliver_during_stale_recovery( mocker: MockerFixture, ) -> None: - """A stale execution must not consume the next distinct scheduled run.""" + """Uncertain worker loss is terminalized before any later delivery.""" state = _make_state_instance( mocker, ReportWorkingState, @@ -2341,27 +2321,25 @@ def test_new_report_execution_proceeds_after_stale_working_cleanup( mocker.patch.object(state, "is_on_working_timeout", return_value=True) working_log = mocker.Mock() working_log.uuid = uuid4() + working_log.state = ReportState.WORKING working_log.end_dttm = datetime.utcnow() - timedelta(minutes=20) mocker.patch( "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", return_value=working_log, ) - cleanup = mocker.patch( - "superset.commands.report.execute.mark_report_execution_terminal_error", - return_value=True, - ) recovered_next = mocker.patch.object(ReportNotTriggeredErrorState, "next") update = mocker.patch.object(state, "update_report_schedule_and_log") - state.next() + with pytest.raises(ReportScheduleWorkingTimeoutError): + state.next() - cleanup.assert_called_once_with( - state._report_schedule.id, - working_log.uuid, - "working_timeout_recovery", + update.assert_called_once_with( + ReportState.ERROR, + error_message=str(ReportScheduleWorkingTimeoutError()), ) - recovered_next.assert_called_once() - update.assert_not_called() + assert working_log.state == ReportState.ERROR + assert working_log.error_message == str(ReportScheduleWorkingTimeoutError()) + recovered_next.assert_not_called() def test_report_working_state_recovery_is_bounded_by_execution_budget( @@ -2410,6 +2388,36 @@ def test_soft_timeout_transitions_report_out_of_working( send_error.assert_not_called() +def test_budget_timeout_transitions_report_without_error_delivery( + mocker: MockerFixture, +) -> None: + state = _make_state_instance( + mocker, + ReportNotTriggeredErrorState, + schedule_type=ReportScheduleType.REPORT, + ) + timeout = ReportExecutionBudgetExceededError( + "chart_readiness", + elapsed_seconds=690, + remaining_seconds=210, + ) + mocker.patch.object(state, "send", side_effect=timeout) + mock_update = mocker.patch.object(state, "update_report_schedule_and_log") + send_error = mocker.patch.object(state, "send_error") + + with pytest.raises(ReportExecutionBudgetExceededError): + state.next() + + assert mock_update.call_args_list == [ + mocker.call(ReportState.WORKING), + mocker.call( + ReportState.ERROR, + error_message="report_execution_budget_exhausted:chart_readiness", + ), + ] + send_error.assert_not_called() + + def test_success_state_grace_period_returns_without_sending( mocker: MockerFixture, ) -> None: @@ -2612,48 +2620,34 @@ def test_create_log_success_commits(mocker: MockerFixture) -> None: mock_db.session.rollback.assert_not_called() -def test_failure_hook_cleanup_promotes_working_log_to_terminal_error( - app: SupersetApp, +def test_create_log_promotes_same_execution_working_row_without_duplicate( mocker: MockerFixture, ) -> None: execution_id = UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524") schedule = mocker.Mock(spec=ReportSchedule) - schedule.last_state = ReportState.WORKING - schedule.dashboard_id = 805 - schedule.chart_id = None + schedule.last_state = ReportState.ERROR + schedule.last_value = None + schedule.last_value_row_json = None working_log = mocker.Mock() - working_log.uuid = execution_id - working_log.report_schedule = schedule mock_db = mocker.patch("superset.commands.report.execute.db") - filtered_query = mock_db.session.query.return_value.filter.return_value - filtered_query.first.return_value = working_log - filtered_query.order_by.return_value.first.return_value = working_log - - assert mark_report_execution_terminal_error( - 11, + mock_db.session.query.return_value.filter.return_value.first.return_value = ( + working_log + ) + log_cls = mocker.patch("superset.commands.report.execute.ReportExecutionLog") + state = BaseReportState( + schedule, + datetime.utcnow(), execution_id, - "celery_task_failure:WorkerLostError", ) - assert working_log.state == ReportState.ERROR - assert working_log.error_message == "celery_task_failure:WorkerLostError" - assert schedule.last_state == ReportState.ERROR - mock_db.session.commit.assert_called_once() - -def test_failure_hook_cleanup_is_idempotent( - app: SupersetApp, - mocker: MockerFixture, -) -> None: - mock_db = mocker.patch("superset.commands.report.execute.db") - mock_db.session.query.return_value.filter.return_value.first.return_value = None + state.create_log(error_message="working timeout") - assert not mark_report_execution_terminal_error( - 11, - UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), - "celery_task_failure:WorkerLostError", - ) - mock_db.session.commit.assert_not_called() + assert working_log.state == ReportState.ERROR + assert working_log.error_message == "working timeout" + log_cls.assert_not_called() + mock_db.session.add.assert_not_called() + mock_db.session.commit.assert_called_once() def test_success_state_report_sends_and_logs_success( diff --git a/tests/unit_tests/utils/test_report_execution.py b/tests/unit_tests/utils/test_report_execution.py index 15d775945a33..6b8ea0abe7e8 100644 --- a/tests/unit_tests/utils/test_report_execution.py +++ b/tests/unit_tests/utils/test_report_execution.py @@ -85,6 +85,25 @@ def test_report_deadline_exhaustion_names_phase() -> None: ) +def test_report_context_rejects_reserves_that_consume_deadline() -> None: + deadline = ReportExecutionDeadline(total_seconds=210) + + with pytest.raises(ValueError, match="must total less"): + ReportExecutionContext( + execution_id=UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + report_schedule_id=7, + deadline=deadline, + capture_reserve_seconds=60, + delivery_reserve_seconds=120, + cleanup_reserve_seconds=30, + ) + + +def test_report_deadline_rejects_nonpositive_budget() -> None: + with pytest.raises(ValueError, match="greater than zero"): + ReportExecutionDeadline(total_seconds=0) + + def test_report_task_limits_align_soft_timeout_with_budget() -> None: config = { "ALERT_REPORTS_WORKING_TIME_OUT_KILL": True, diff --git a/tests/unit_tests/utils/test_screenshot_utils.py b/tests/unit_tests/utils/test_screenshot_utils.py index 142efe43ebc8..219f793f6874 100644 --- a/tests/unit_tests/utils/test_screenshot_utils.py +++ b/tests/unit_tests/utils/test_screenshot_utils.py @@ -17,10 +17,15 @@ import io from unittest.mock import MagicMock, patch +from uuid import UUID import pytest -from PIL import Image +from PIL import Image, UnidentifiedImageError +from superset.utils.report_execution import ( + ReportExecutionContext, + ReportExecutionDeadline, +) from superset.utils.screenshot_utils import ( combine_screenshot_tiles, resolve_screenshot_task_budget_seconds, @@ -30,6 +35,25 @@ ) +def _report_context() -> ReportExecutionContext: + """Return a deterministic context with 30 seconds available for readiness.""" + + return ReportExecutionContext( + execution_id=UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + report_schedule_id=11, + dashboard_id=805, + expected_chart_count=52, + deadline=ReportExecutionDeadline( + total_seconds=240, + started_at=0, + _clock=lambda: 0, + ), + capture_reserve_seconds=60, + delivery_reserve_seconds=120, + cleanup_reserve_seconds=30, + ) + + class TestResolveScreenshotTaskBudget: def _task(self, timelimit): task = MagicMock() @@ -152,6 +176,16 @@ def test_combine_tiles_logs_exception(self): # Should return first tile as fallback assert result == valid_tile + def test_report_mode_rejects_partial_first_tile_fallback(self): + """A report must not turn a tile-combine failure into a partial image.""" + + valid_tile = self._create_test_image(100, 100) + with pytest.raises(UnidentifiedImageError): + combine_screenshot_tiles( + [valid_tile, b"invalid_image_data"], + allow_partial_fallback=False, + ) + class TestTakeTiledScreenshot: @pytest.fixture @@ -233,6 +267,7 @@ def screenshot(**kwargs): "dashboard", tile_height=2000, load_wait=30, + report_execution_context=_report_context(), ) assert result == b"combined" @@ -251,6 +286,7 @@ def test_zero_holders_timeout_before_dimensions_or_capture(self, mock_page): "dashboard", tile_height=2000, load_wait=30, + report_execution_context=_report_context(), ) assert mock_page.evaluate.call_count == 1 @@ -457,7 +493,11 @@ 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 + mock_page, + "dashboard", + tile_height=2000, + load_wait=30, + report_execution_context=_report_context(), ) # One initial holder-mount gate, then one readiness poll per tile. @@ -496,7 +536,11 @@ def test_per_tile_readiness_timeout_raises_and_skips_capture(self, mock_page): with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): with pytest.raises(PlaywrightTimeout): take_tiled_screenshot( - mock_page, "dashboard", tile_height=2000, load_wait=30 + mock_page, + "dashboard", + tile_height=2000, + load_wait=30, + report_execution_context=_report_context(), ) # No tile should have been captured -- fail loudly, don't snapshot @@ -520,7 +564,7 @@ def test_per_tile_readiness_timeout_raises_and_skips_capture(self, mock_page): assert isinstance(warning_args[7], float) # tile elapsed assert isinstance(warning_args[8], float) # total elapsed assert warning_args[10] == 30 # effective wait - assert warning_args[11] == "" # no log_context passed + assert "capture_kind=report" in warning_args[11] # 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. @@ -531,10 +575,7 @@ def test_timeout_warning_includes_log_context(self, mock_page): correlation with the run that triggered this screenshot.""" from superset.utils.screenshot_utils import PlaywrightTimeout - mock_page.wait_for_function.side_effect = [ - None, - PlaywrightTimeout("timed out"), - ] + mock_page.wait_for_function.side_effect = PlaywrightTimeout("timed out") mock_page.evaluate.side_effect = [ {"height": 2000, "top": 0, "left": 0, "width": 800}, None, @@ -590,7 +631,7 @@ def fake_wait_for_function(js, timeout=None): mock_page, "dashboard", tile_height=2000, load_wait=5 ) - assert js_call_count["n"] == 2 + assert js_call_count["n"] == 1 mock_page.screenshot.assert_not_called() def test_unready_holder_state_classification_embedded_in_js(self, mock_page): @@ -605,6 +646,7 @@ def test_unready_holder_state_classification_embedded_in_js(self, mock_page): CHART_HOLDERS_READY_JS, FIND_CHART_HOLDER_STATES_JS, FIND_UNREADY_CHART_HOLDERS_JS, + REPORT_CHART_HOLDERS_READY_JS, ) for js in (CHART_HOLDERS_READY_JS, FIND_UNREADY_CHART_HOLDERS_JS): @@ -616,7 +658,8 @@ def test_unready_holder_state_classification_embedded_in_js(self, mock_page): '.dashboard-component-chart-holder[class*="dashboard-chart-id-"]' ) in js assert "holder.className.match(/\\bdashboard-chart-id-(\\d+)\\b/)" in js - assert "holders.length > 0" in CHART_HOLDERS_READY_JS + assert "holders.length > 0" not in CHART_HOLDERS_READY_JS + assert "holders.length > 0" in REPORT_CHART_HOLDERS_READY_JS assert "rendered" in FIND_CHART_HOLDER_STATES_JS assert "empty" in FIND_CHART_HOLDER_STATES_JS @@ -633,6 +676,7 @@ def test_readiness_constants_are_production_safe(self): CHART_HOLDERS_READY_JS, FIND_CHART_HOLDER_STATES_JS, FIND_UNREADY_CHART_HOLDERS_JS, + REPORT_CHART_HOLDERS_READY_JS, ) for js in ( @@ -640,6 +684,7 @@ def test_readiness_constants_are_production_safe(self): CHART_HOLDERS_READY_JS, FIND_CHART_HOLDER_STATES_JS, FIND_UNREADY_CHART_HOLDERS_JS, + REPORT_CHART_HOLDERS_READY_JS, ): assert "data-test" not in js @@ -682,10 +727,33 @@ def test_all_chart_holders_ready_passes(self, mock_page): # 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 == 4 + assert mock_page.wait_for_function.call_count == 3 assert mock_page.screenshot.call_count == 3 assert result is not None + def test_thumbnail_zero_holders_preserves_existing_capture_behavior( + self, + mock_page, + ): + """The report-only mount gate must not make empty thumbnails time out.""" + + with patch( + "superset.utils.screenshot_utils.combine_screenshot_tiles", + return_value=b"thumbnail", + ): + result = take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + load_wait=30, + ) + + assert result == b"thumbnail" + assert mock_page.wait_for_function.call_count == 3 + predicate = mock_page.wait_for_function.call_args_list[0].args[0] + assert "holders.length > 0" not in predicate + assert mock_page.screenshot.call_count == 3 + def test_load_wait_default_is_sixty_seconds(self): """load_wait defaults to 60 to match SCREENSHOT_LOAD_WAIT config default.""" import inspect diff --git a/tests/unit_tests/utils/webdriver_test.py b/tests/unit_tests/utils/webdriver_test.py index 4c621f512541..6dedc15624c2 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -16,9 +16,14 @@ # under the License. from unittest.mock import MagicMock, patch, PropertyMock +from uuid import UUID import pytest +from superset.utils.report_execution import ( + ReportExecutionContext, + ReportExecutionDeadline, +) from superset.utils.webdriver import ( check_playwright_availability, PLAYWRIGHT_AVAILABLE, @@ -29,6 +34,31 @@ ) +def _report_context( + *, + dashboard_id: int | None = 805, + chart_id: int | None = None, + expected_chart_count: int = 52, +) -> ReportExecutionContext: + """Return a deterministic scheduled-report context.""" + + return ReportExecutionContext( + execution_id=UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + report_schedule_id=11, + dashboard_id=dashboard_id, + chart_id=chart_id, + expected_chart_count=expected_chart_count, + deadline=ReportExecutionDeadline( + total_seconds=900, + started_at=0, + _clock=lambda: 0, + ), + capture_reserve_seconds=60, + delivery_reserve_seconds=120, + cleanup_reserve_seconds=30, + ) + + @pytest.fixture() def mock_app(): """Mock Flask app with webdriver configuration.""" @@ -303,6 +333,55 @@ def test_driver_skips_page_load_timeout_when_none( assert driver.driver is mock_driver mock_driver.set_page_load_timeout.assert_not_called() + @patch("superset.utils.webdriver.WebDriverWait") + @patch("superset.utils.webdriver.app") + def test_report_chart_uses_chart_readiness_not_dashboard_holders( + self, + mock_app_patch: MagicMock, + mock_wait: MagicMock, + ) -> None: + """Selenium chart reports require their chart terminal marker.""" + from selenium.common.exceptions import TimeoutException + + mock_app_patch.config = { + "SCREENSHOT_LOCATE_WAIT": 10, + "SCREENSHOT_LOAD_WAIT": 60, + "SCREENSHOT_PAGE_LOAD_WAIT": 120, + "SCREENSHOT_SELENIUM_HEADSTART": 0, + "SCREENSHOT_SELENIUM_ANIMATION_WAIT": 0, + "SCREENSHOT_REPLACE_UNEXPECTED_ERRORS": False, + } + mock_driver = MagicMock() + element = MagicMock() + mount_wait = MagicMock() + mount_wait.until.return_value = element + readiness_wait = MagicMock() + readiness_wait.until.side_effect = TimeoutException() + mock_wait.side_effect = [mount_wait, readiness_wait] + screenshot = WebDriverSelenium(driver_type="chrome") + screenshot._driver = mock_driver + + with ( + patch("superset.utils.webdriver.sleep"), + pytest.raises(TimeoutException), + ): + screenshot.get_screenshot( + "http://example.com/chart/7", + "chart-container", + report_execution_context=_report_context( + dashboard_id=None, + chart_id=7, + expected_chart_count=1, + ), + ) + + predicate = readiness_wait.until.call_args.args[0] + predicate(mock_driver) + readiness_js = mock_driver.execute_script.call_args.args[0] + assert "document.querySelector('.chart-container')" in readiness_js + assert "dashboard-component-chart-holder" not in readiness_js + assert element.screenshot_as_png.call_count == 0 + class TestPlaywrightAvailabilityCheck: """Test comprehensive Playwright availability checking.""" @@ -982,15 +1061,18 @@ def evaluate_side_effect(script): driver = WebDriverPlaywright("chrome") with pytest.raises(PlaywrightTimeout): - driver.get_screenshot("http://example.com", "standalone", mock_user) + driver.get_screenshot( + "http://example.com", + "standalone", + mock_user, + report_execution_context=_report_context(), + ) mock_take_tiled.assert_called_once() mock_page.screenshot.assert_not_called() - mock_logger.warning.assert_any_call( - "Tiled screenshot failed for url %s%s and no safe " - "fallback exists; terminal_reason=tiled_capture_failed", - "http://example.com", - "", + assert any( + "no safe fallback exists" in call.args[0] + for call in mock_logger.warning.call_args_list ) @@ -1119,7 +1201,14 @@ def test_chart_capture_uses_positive_terminal_state_predicate( with patch.object(WebDriverPlaywright, "auth", return_value=mock_context): with pytest.raises(PlaywrightTimeout): WebDriverPlaywright("chrome").get_screenshot( - "http://example.com", "chart-container", MagicMock() + "http://example.com", + "chart-container", + MagicMock(), + report_execution_context=_report_context( + dashboard_id=None, + chart_id=7, + expected_chart_count=1, + ), ) predicate = mock_page.wait_for_function.call_args.args[0] @@ -1148,7 +1237,10 @@ def test_standalone_zero_holders_remain_not_ready_and_skip_capture( with patch.object(WebDriverPlaywright, "auth", return_value=mock_context): with pytest.raises(PlaywrightTimeout): WebDriverPlaywright("chrome").get_screenshot( - "http://example.com", "standalone", MagicMock() + "http://example.com", + "standalone", + MagicMock(), + report_execution_context=_report_context(), ) assert any( @@ -1160,6 +1252,29 @@ def test_standalone_zero_holders_remain_not_ready_and_skip_capture( ) mock_page.screenshot.assert_not_called() + @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) + @patch("superset.utils.webdriver._browser_manager") + @patch("superset.utils.webdriver.app") + def test_thumbnail_zero_holders_preserves_existing_capture_behavior( + self, + mock_app, + mock_browser_manager, + ): + mock_app.config = {**self._base_config} + mock_context, mock_page = self._make_pw_mocks(mock_browser_manager) + mock_page.evaluate.return_value = [] + + with patch.object(WebDriverPlaywright, "auth", return_value=mock_context): + result = WebDriverPlaywright("chrome").get_screenshot( + "http://example.com", + "standalone", + MagicMock(), + ) + + predicate = mock_page.wait_for_function.call_args.args[0] + assert "holders.length > 0" not in predicate + assert result == mock_page.screenshot.return_value + @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @patch("superset.utils.webdriver.app") @@ -1594,11 +1709,10 @@ def test_tiled_path_passes_animation_wait_per_tile_no_global_wait( @patch("superset.utils.webdriver._browser_manager") @patch("superset.utils.webdriver.take_tiled_screenshot") @patch("superset.utils.webdriver.app") - def test_tiled_empty_bytes_raise_without_unguarded_fallback( + def test_tiled_empty_bytes_preserve_thumbnail_fallback( self, mock_app, mock_take_tiled, mock_browser_manager ): - """Empty tiled output fails instead of invoking raw full-page capture.""" - from superset.utils.webdriver import PlaywrightTimeout + """The strict no-fallback rule must not change thumbnail behavior.""" mock_user = MagicMock() mock_user.username = "test_user" @@ -1619,14 +1733,14 @@ def test_tiled_empty_bytes_raise_without_unguarded_fallback( mock_page.screenshot.return_value = b"fallback" with patch.object(WebDriverPlaywright, "auth", return_value=mock_context): - with pytest.raises(PlaywrightTimeout): - WebDriverPlaywright("chrome").get_screenshot( - "http://example.com", "standalone", mock_user - ) + result = WebDriverPlaywright("chrome").get_screenshot( + "http://example.com", "standalone", mock_user + ) # Tiled path was taken (take_tiled_screenshot was called) mock_take_tiled.assert_called_once() - mock_page.screenshot.assert_not_called() + mock_page.screenshot.assert_called_once_with(full_page=True) + assert result == b"fallback" @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") From 7236b4c4e855b0f4e196c95f93b5f7ab32eba0b6 Mon Sep 17 00:00:00 2001 From: Mafi Date: Thu, 30 Jul 2026 23:50:11 +0000 Subject: [PATCH 03/19] style(reports): apply pinned Ruff formatting --- tests/unit_tests/utils/webdriver_test.py | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/tests/unit_tests/utils/webdriver_test.py b/tests/unit_tests/utils/webdriver_test.py index 6dedc15624c2..31f621fe3f79 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -1607,9 +1607,9 @@ def record_wait_for_timeout(ms): assert "animation_wait" in call_order spinner_idx = call_order.index("spinner_wait") anim_idx = call_order.index("animation_wait") - assert ( - spinner_idx < anim_idx - ), "spinner wait must precede animation wait in non-tiled path" + assert spinner_idx < anim_idx, ( + "spinner wait must precede animation wait in non-tiled path" + ) @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -1701,9 +1701,9 @@ def test_tiled_path_passes_animation_wait_per_tile_no_global_wait( for call in mock_page.wait_for_timeout.call_args_list if call[0][0] == 2 * 1000 ] - assert ( - animation_waits == [] - ), "No global 2s animation wait_for_timeout should fire on the tiled path" + assert animation_waits == [], ( + "No global 2s animation wait_for_timeout should fire on the tiled path" + ) @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @@ -1766,6 +1766,6 @@ def test_animation_wait_skipped_when_zero(self, mock_app, mock_browser_manager): timeout_values = [ call[0][0] for call in mock_page.wait_for_timeout.call_args_list ] - assert timeout_values == [ - 0 - ], f"Expected only [0] (headstart), got {timeout_values}" + assert timeout_values == [0], ( + f"Expected only [0] (headstart), got {timeout_values}" + ) From 3f232a218b6b703fef684de5acba34496155504b Mon Sep 17 00:00:00 2001 From: Mafi Date: Fri, 31 Jul 2026 00:13:51 +0000 Subject: [PATCH 04/19] fix(reports): preserve alert timeout semantics --- superset/commands/report/execute.py | 31 +++++++++++---- .../reports/commands_tests.py | 16 ++++---- .../commands/report/execute_test.py | 38 +++++++++++++++++++ 3 files changed, 68 insertions(+), 17 deletions(-) diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index d46e42d80627..e0fbfda06041 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -38,7 +38,9 @@ ReportScheduleAlertGracePeriodError, ReportScheduleClientErrorsException, ReportScheduleCsvFailedError, + ReportScheduleCsvTimeout, ReportScheduleDataFrameFailedError, + ReportScheduleDataFrameTimeout, ReportScheduleExecuteUnexpectedError, ReportScheduleExecutorNotFoundError, ReportScheduleNotFoundError, @@ -52,6 +54,7 @@ ReportScheduleUnexpectedError, ReportScheduleWorkingTimeoutError, ReportScheduleXlsxFailedError, + ReportScheduleXlsxTimeout, ) from superset.common.chart_data import ChartDataResultFormat, ChartDataResultType from superset.daos.report import ( @@ -687,7 +690,7 @@ def _get_screenshots(self) -> list[bytes]: ), len(imges), ) - except SoftTimeLimitExceeded: + except SoftTimeLimitExceeded as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() @@ -702,7 +705,12 @@ def _get_screenshots(self) -> list[bytes]: else None ), ) - raise + if self._report_schedule.type == ReportScheduleType.REPORT: + raise + # Alerts that attach a screenshot retain their established + # format-specific timeout and error-notification behavior. Report + # executions propagate the Celery signal to terminal cleanup. + raise ReportScheduleScreenshotTimeout() from ex except ReportExecutionBudgetExceededError: raise except Exception as ex: @@ -867,15 +875,18 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: f"Unsupported chart data result format: {result_format}" ) + timeout_error: type[CommandException] failed_error: type[CommandException] if result_format == ChartDataResultFormat.XLSX: - label, failed_error = ( + label, timeout_error, failed_error = ( "Excel", + ReportScheduleXlsxTimeout, ReportScheduleXlsxFailedError, ) else: - label, failed_error = ( + label, timeout_error, failed_error = ( "CSV", + ReportScheduleCsvTimeout, ReportScheduleCsvFailedError, ) @@ -936,7 +947,7 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: elapsed_seconds, self._execution_id, ) - except SoftTimeLimitExceeded: + except SoftTimeLimitExceeded as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() @@ -946,7 +957,9 @@ def _get_data(self, result_format: ChartDataResultFormat) -> bytes: elapsed_seconds, self._execution_id, ) - raise + if self._report_schedule.type == ReportScheduleType.REPORT: + raise + raise timeout_error() from ex except ReportExecutionBudgetExceededError: raise except Exception as ex: @@ -1002,7 +1015,7 @@ def _get_embedded_data(self) -> pd.DataFrame: elapsed_seconds, self._execution_id, ) - except SoftTimeLimitExceeded: + except SoftTimeLimitExceeded as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time ).total_seconds() @@ -1011,7 +1024,9 @@ def _get_embedded_data(self) -> pd.DataFrame: elapsed_seconds, self._execution_id, ) - raise + if self._report_schedule.type == ReportScheduleType.REPORT: + raise + raise ReportScheduleDataFrameTimeout() from ex except ReportExecutionBudgetExceededError: raise except Exception as ex: diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index ddbe19977d10..c86b48f4df7d 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -52,7 +52,6 @@ AlertQueryMultipleRowsError, ReportScheduleClientErrorsException, ReportScheduleCsvFailedError, - ReportScheduleCsvTimeout, ReportScheduleNotFoundError, ReportSchedulePreviousWorkingError, ReportScheduleScreenshotFailedError, @@ -2328,19 +2327,18 @@ def test_soft_timeout_csv( mock_urlopen.return_value = response mock_urlopen.return_value.getcode.side_effect = SoftTimeLimitExceeded() - with pytest.raises(ReportScheduleCsvTimeout): + with pytest.raises(SoftTimeLimitExceeded): AsyncExecuteReportScheduleCommand( TEST_ID, create_report_email_chart_with_csv.id, datetime.utcnow() ).run() - get_target_from_report_schedule(create_report_email_chart_with_csv) # noqa: F841 - # Assert the email smtp address, asserts a notification was sent with the error - assert email_mock.call_args[0][0] == DEFAULT_OWNER_EMAIL + # Reports preserve the hard-limit grace for terminal persistence instead + # of attempting an error notification after Celery's soft deadline. + email_mock.assert_not_called() - assert_log( - ReportState.ERROR, - error_message="A timeout occurred while generating a csv.", - ) + logs = get_error_logs_query(create_report_email_chart_with_csv).all() + assert len(logs) == 1 + assert logs[0].error_message == "celery_soft_timeout" @pytest.mark.usefixtures( diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index 2687588ffb53..f7f8172e7608 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -1691,6 +1691,44 @@ def test_get_data_xlsx_propagates_celery_soft_time_limit( report_state._get_data(ChartDataResultFormat.XLSX) +@pytest.mark.parametrize( + ("schedule_type", "expected_exception"), + [ + (ReportScheduleType.REPORT, SoftTimeLimitExceeded), + (ReportScheduleType.ALERT, ReportScheduleScreenshotTimeout), + ], +) +def test_screenshot_soft_timeout_distinguishes_reports_from_alert_attachments( + app: SupersetApp, + mocker: MockerFixture, + schedule_type: ReportScheduleType, + expected_exception: type[Exception], +) -> None: + """Only reports reserve hard-limit grace for terminal cleanup.""" + app.config.update( + { + "ALERT_REPORTS_MAX_CUSTOM_SCREENSHOT_WIDTH": 1600, + "WEBDRIVER_WINDOW": {"slice": (800, 600), "dashboard": (800, 600)}, + } + ) + schedule = create_report_schedule(mocker) + schedule.type = schedule_type + schedule.chart.digest = "chart-digest" + state = BaseReportState(schedule, datetime.now(), uuid4()) + mocker.patch( + "superset.commands.report.execute.resolve_executor_user", + return_value=(mocker.MagicMock(), "executor"), + ) + mocker.patch.object(state, "_get_url", return_value="/chart/1") + screenshot = mocker.patch( + "superset.commands.report.execute.ChartScreenshot" + ).return_value + screenshot.get_screenshot.side_effect = SoftTimeLimitExceeded() + + with pytest.raises(expected_exception): + state._get_screenshots() + + def test_executor_not_found_error_message_without_username() -> None: """ When no username is available, the message falls back to ``(unknown)`` From 830e6cb5d532f470c247b7c6c99712cb388bc6bd Mon Sep 17 00:00:00 2001 From: Mafi Date: Fri, 31 Jul 2026 01:45:16 +0000 Subject: [PATCH 05/19] fix(reports): address reliability review --- .../configuration/alerts-reports.mdx | 11 +++ superset/commands/report/execute.py | 27 ++--- superset/initialization/__init__.py | 2 + superset/tasks/scheduler.py | 1 + superset/utils/report_execution.py | 32 +++++- superset/utils/webdriver.py | 8 +- .../reports/commands_tests.py | 3 +- .../reports/scheduler_tests.py | 35 +++++++ .../commands/report/execute_test.py | 7 +- .../commands/report/test_execute_now.py | 3 + tests/unit_tests/initialization_test.py | 19 ++++ .../unit_tests/utils/test_report_execution.py | 54 ++++++++-- tests/unit_tests/utils/webdriver_test.py | 98 ++++++++++++++++++- 13 files changed, 258 insertions(+), 42 deletions(-) diff --git a/docs/admin_docs/configuration/alerts-reports.mdx b/docs/admin_docs/configuration/alerts-reports.mdx index 2eee8fd16e97..3aa1af49acf6 100644 --- a/docs/admin_docs/configuration/alerts-reports.mdx +++ b/docs/admin_docs/configuration/alerts-reports.mdx @@ -261,6 +261,17 @@ ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS = 30 # Celery limits; disabling it does not disable the application deadline above. ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS = 30 +# Invalid budget/reserve combinations fail application startup instead of +# allowing every scheduled report to fail later. A report Celery soft timeout +# records ERROR and increments `reports.execute.celery_soft_timeout`; it does +# not attempt an in-band customer error notification during the hard-limit +# grace window. Alert schedules retain their existing timeout notifications. +# +# The application deadline is cooperative between synchronous phases. The +# Celery limits provide the final preemption boundary when the worker pool +# supports them; PDF construction is checked immediately before and after the +# synchronous builder but cannot be interrupted inside that call. + # Screenshot-specific waits continue to apply to thumbnails and other # standalone screenshot calls. Scheduled reports derive their waits from the # shared execution deadline above. diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index e0fbfda06041..820bfa4acd2f 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -1500,27 +1500,12 @@ def next(self) -> None: self._execution_id, ) exception_timeout = ReportScheduleWorkingTimeoutError() - if last_working and last_working.uuid != self._execution_id: - # This invocation is the first application-owned opportunity to - # recover a worker-lost execution. Terminalize the stale row in - # the same session as the recovery invocation's ERROR row; the - # create_log() commit below persists both changes together. - last_working.state = ReportState.ERROR - last_working.error_message = str(exception_timeout) - last_working.end_dttm = datetime.now(timezone.utc).replace(tzinfo=None) - logger.info( - "report_execution_terminal %s lost_execution_id=%s " - "state=%s terminal_reason=working_timeout_recovered", - self._log_context, - last_working.uuid, - ReportState.ERROR.value, - ) - # Keep the established state-machine recovery transaction: the - # recovery invocation records ERROR and stops. If it reuses the - # original execution id, create_log promotes that exact WORKING row; - # a distinct id terminalizes the lost row and records its own ERROR - # without risking an uncertain duplicate delivery after worker loss. - # The following schedule can start from ERROR normally. + # Keep recovery owned by this invocation. If it reuses the original + # execution id, create_log promotes that exact WORKING row. A distinct + # invocation must not mutate the old audit row: Celery hard limits do + # not preempt every worker pool, so the original worker may still be + # alive. The recovery ERROR still unblocks the schedule without risking + # a lost update or uncertain duplicate delivery. self.update_report_schedule_and_log( ReportState.ERROR, error_message=str(exception_timeout), diff --git a/superset/initialization/__init__.py b/superset/initialization/__init__.py index 851dc04a7753..f8e1ba1ed658 100644 --- a/superset/initialization/__init__.py +++ b/superset/initialization/__init__.py @@ -75,6 +75,7 @@ from superset.utils.core import is_test, pessimistic_connection_handling from superset.utils.decorators import transaction from superset.utils.log import DBEventLogger, get_event_logger_from_cfg_value +from superset.utils.report_execution import validate_report_execution_config if TYPE_CHECKING: from superset.app import SupersetApp @@ -123,6 +124,7 @@ def pre_init(self) -> None: """ Called before all other init tasks are complete """ + validate_report_execution_config(self.config) wtforms_json.init() os.makedirs(self.config["DATA_DIR"], exist_ok=True) diff --git a/superset/tasks/scheduler.py b/superset/tasks/scheduler.py index 8a24180ebe28..9435eb650efe 100644 --- a/superset/tasks/scheduler.py +++ b/superset/tasks/scheduler.py @@ -131,6 +131,7 @@ def execute(self: Task, report_schedule_id: int) -> None: scheduled_dttm, ).run() except SoftTimeLimitExceeded: + stats_logger.incr("reports.execute.celery_soft_timeout") logger.warning( "Alert/report execution hit Celery soft timeout; execution_id=%s " "report_schedule_id=%s terminal_reason=celery_soft_timeout", diff --git a/superset/utils/report_execution.py b/superset/utils/report_execution.py index c3e0e63c0249..71630451166e 100644 --- a/superset/utils/report_execution.py +++ b/superset/utils/report_execution.py @@ -25,6 +25,31 @@ from uuid import UUID +def validate_report_execution_config(config: Mapping[str, Any]) -> None: + """Validate the scheduled-report budget invariant during application startup.""" + + budget = float(config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"]) + reserves = ( + float(config["ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS"]), + float(config["ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS"]), + float(config["ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS"]), + ) + hard_timeout_grace = float( + config["ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS"] + ) + + if budget <= 0: + raise ValueError("Report execution budget must be greater than zero") + if any(reserve < 0 for reserve in reserves): + raise ValueError("Report execution phase reserves cannot be negative") + if sum(reserves) >= budget: + raise ValueError( + "Report execution phase reserves must total less than the execution budget" + ) + if hard_timeout_grace < 0: + raise ValueError("Report execution hard-timeout grace cannot be negative") + + class ReportExecutionBudgetExceededError(TimeoutError): """Raised before a report phase would overrun its execution deadline.""" @@ -171,16 +196,13 @@ def get_report_task_timeout_options( ) -> dict[str, int]: """Return Celery time limits aligned with the application execution budget.""" + if is_report: + validate_report_execution_config(config) if not config["ALERT_REPORTS_WORKING_TIME_OUT_KILL"]: return {} if is_report: budget = int(config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"]) hard_grace = int(config["ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS"]) - if budget <= 0 or hard_grace < 0: - raise ValueError( - "Report execution budget must be positive and hard-timeout " - "grace cannot be negative" - ) return { "soft_time_limit": budget, "time_limit": budget + hard_grace, diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index 5ae3dcc4c65e..15d21f742e1a 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -708,10 +708,10 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n ) # Use tiled screenshots for large dashboards - use_tiled = chart_count >= chart_threshold or ( - dashboard_height > height_threshold - and dashboard_height > tile_height - ) + use_tiled = ( + chart_count >= chart_threshold + or dashboard_height > height_threshold + ) and dashboard_height > tile_height if use_tiled: logger.info( diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index c86b48f4df7d..6ea428d984af 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -1953,7 +1953,8 @@ def test_report_schedule_working_timeout(create_report_slack_chart_working): assert ReportScheduleWorkingTimeoutError.message in [ log.error_message for log in logs ] - assert {log.state for log in logs} == {ReportState.ERROR} + assert sum(log.state == ReportState.WORKING for log in logs) == 1 + assert sum(log.state == ReportState.ERROR for log in logs) == 1 assert create_report_slack_chart_working.last_state == ReportState.ERROR diff --git a/tests/integration_tests/reports/scheduler_tests.py b/tests/integration_tests/reports/scheduler_tests.py index 48b3df0e75bb..60d958cba180 100644 --- a/tests/integration_tests/reports/scheduler_tests.py +++ b/tests/integration_tests/reports/scheduler_tests.py @@ -197,6 +197,41 @@ def test_execute_task(update_state_mock, command_mock, init_mock, editors): db.session.commit() +@pytest.mark.usefixtures("app_context") +@patch("superset.commands.report.execute.AsyncExecuteReportScheduleCommand.__init__") +@patch("superset.commands.report.execute.AsyncExecuteReportScheduleCommand.run") +@patch("superset.tasks.scheduler.execute.update_state") +def test_execute_soft_timeout_emits_operator_metric( + update_state_mock, + command_mock, + init_mock, + editors, +): + from celery.exceptions import SoftTimeLimitExceeded + + report_schedule = insert_report_schedule( + type=ReportScheduleType.REPORT, + name=f"report-{randint(0, 1000)}", # noqa: S311 + crontab="0 4 * * *", + timezone="America/New_York", + editors=editors, + ) + stats_logger = MagicMock() + init_mock.return_value = None + command_mock.side_effect = SoftTimeLimitExceeded() + + with ( + patch.dict(app.config, {"STATS_LOGGER": stats_logger}), + pytest.raises(SoftTimeLimitExceeded), + ): + execute(report_schedule.id) + + stats_logger.incr.assert_any_call("reports.execute.celery_soft_timeout") + update_state_mock.assert_called_once_with(state="FAILURE") + db.session.delete(report_schedule) + db.session.commit() + + @pytest.mark.usefixtures("app_context") @patch("superset.commands.report.execute.AsyncExecuteReportScheduleCommand.__init__") @patch("superset.commands.report.execute.AsyncExecuteReportScheduleCommand.run") diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index f7f8172e7608..a57c0b73cfd7 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -2349,7 +2349,7 @@ def test_working_timeout_replay_promotes_original_execution_without_duplicate_lo def test_new_report_execution_does_not_deliver_during_stale_recovery( mocker: MockerFixture, ) -> None: - """Uncertain worker loss is terminalized before any later delivery.""" + """Recovery unblocks the schedule without racing the old worker's audit row.""" state = _make_state_instance( mocker, ReportWorkingState, @@ -2360,6 +2360,7 @@ def test_new_report_execution_does_not_deliver_during_stale_recovery( working_log = mocker.Mock() working_log.uuid = uuid4() working_log.state = ReportState.WORKING + working_log.error_message = None working_log.end_dttm = datetime.utcnow() - timedelta(minutes=20) mocker.patch( "superset.commands.report.execute.ReportScheduleDAO.find_last_entered_working_log", @@ -2375,8 +2376,8 @@ def test_new_report_execution_does_not_deliver_during_stale_recovery( ReportState.ERROR, error_message=str(ReportScheduleWorkingTimeoutError()), ) - assert working_log.state == ReportState.ERROR - assert working_log.error_message == str(ReportScheduleWorkingTimeoutError()) + assert working_log.state == ReportState.WORKING + assert working_log.error_message is None recovered_next.assert_not_called() diff --git a/tests/unit_tests/commands/report/test_execute_now.py b/tests/unit_tests/commands/report/test_execute_now.py index de6665d562db..dd1a0caa12ed 100644 --- a/tests/unit_tests/commands/report/test_execute_now.py +++ b/tests/unit_tests/commands/report/test_execute_now.py @@ -229,6 +229,9 @@ def test_execute_now_report_uses_end_to_end_budget_time_limits() -> None: mock_app.config = { "ALERT_REPORTS_WORKING_TIME_OUT_KILL": True, "ALERT_REPORTS_EXECUTION_BUDGET_SECONDS": 900, + "ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS": 60, + "ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS": 120, + "ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS": 30, "ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS": 30, } ExecuteReportScheduleNowCommand(1).run() diff --git a/tests/unit_tests/initialization_test.py b/tests/unit_tests/initialization_test.py index e68560906cee..7ed62f426d02 100644 --- a/tests/unit_tests/initialization_test.py +++ b/tests/unit_tests/initialization_test.py @@ -120,6 +120,25 @@ def test_sync_config_to_db_initializes_when_tables_exist( class TestSupersetAppInitializer: + @patch("superset.initialization.os.makedirs") + @patch("superset.initialization.wtforms_json.init") + @patch("superset.initialization.validate_report_execution_config") + def test_pre_init_validates_report_budget_at_boot( + self, + validate_report_config, + wtforms_init, + makedirs, + ) -> None: + mock_app = MagicMock() + mock_app.config = {"DATA_DIR": "/var/lib/superset"} + app_initializer = SupersetAppInitializer(mock_app) + + app_initializer.pre_init() + + validate_report_config.assert_called_once_with(mock_app.config) + wtforms_init.assert_called_once_with() + makedirs.assert_called_once_with("/var/lib/superset", exist_ok=True) + @patch("superset.initialization.logger") def test_init_app_in_ctx_calls_sync_config_to_db(self, mock_logger): """Test that initialization calls app.sync_config_to_db().""" diff --git a/tests/unit_tests/utils/test_report_execution.py b/tests/unit_tests/utils/test_report_execution.py index 6b8ea0abe7e8..5545bbf6e6c2 100644 --- a/tests/unit_tests/utils/test_report_execution.py +++ b/tests/unit_tests/utils/test_report_execution.py @@ -23,9 +23,25 @@ ReportExecutionBudgetExceededError, ReportExecutionContext, ReportExecutionDeadline, + validate_report_execution_config, ) +def _report_config(**overrides: int) -> dict[str, int | bool]: + config: dict[str, int | bool] = { + "ALERT_REPORTS_WORKING_TIME_OUT_KILL": True, + "ALERT_REPORTS_EXECUTION_BUDGET_SECONDS": 900, + "ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS": 60, + "ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS": 120, + "ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS": 30, + "ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS": 30, + "ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG": 1, + "ALERT_REPORTS_WORKING_TIME_OUT_LAG": 10, + } + config.update(overrides) + return config + + def test_report_deadline_derives_phase_timeout_from_one_clock() -> None: clock_value = 100.0 deadline = ReportExecutionDeadline( @@ -105,13 +121,7 @@ def test_report_deadline_rejects_nonpositive_budget() -> None: def test_report_task_limits_align_soft_timeout_with_budget() -> None: - config = { - "ALERT_REPORTS_WORKING_TIME_OUT_KILL": True, - "ALERT_REPORTS_EXECUTION_BUDGET_SECONDS": 900, - "ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS": 30, - "ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG": 1, - "ALERT_REPORTS_WORKING_TIME_OUT_LAG": 10, - } + config = _report_config() assert get_report_task_timeout_options( is_report=True, @@ -123,3 +133,33 @@ def test_report_task_limits_align_soft_timeout_with_budget() -> None: working_timeout=3600, config=config, ) == {"soft_time_limit": 3601, "time_limit": 3610} + + +@pytest.mark.parametrize( + ("overrides", "message"), + [ + ({"ALERT_REPORTS_EXECUTION_BUDGET_SECONDS": 0}, "greater than zero"), + ( + {"ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS": -1}, + "cannot be negative", + ), + ( + {"ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS": 810}, + "must total less", + ), + ( + {"ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS": -1}, + "grace cannot be negative", + ), + ], +) +def test_report_execution_config_rejects_invalid_startup_values( + overrides: dict[str, int], + message: str, +) -> None: + with pytest.raises(ValueError, match=message): + validate_report_execution_config(_report_config(**overrides)) + + +def test_report_execution_config_accepts_defaults() -> None: + validate_report_execution_config(_report_config()) diff --git a/tests/unit_tests/utils/webdriver_test.py b/tests/unit_tests/utils/webdriver_test.py index 31f621fe3f79..733ae984e062 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -15,7 +15,7 @@ # specific language governing permissions and limitations # under the License. -from unittest.mock import MagicMock, patch, PropertyMock +from unittest.mock import call, MagicMock, patch, PropertyMock from uuid import UUID import pytest @@ -382,6 +382,72 @@ def test_report_chart_uses_chart_readiness_not_dashboard_holders( assert "dashboard-component-chart-holder" not in readiness_js assert element.screenshot_as_png.call_count == 0 + @patch("superset.utils.webdriver.sleep") + @patch("superset.utils.webdriver.WebDriverWait") + @patch("superset.utils.webdriver.app") + def test_report_dashboard_budget_wires_selenium_timeouts_in_seconds( + self, + mock_app_patch: MagicMock, + mock_wait: MagicMock, + mock_sleep: MagicMock, + ) -> None: + """Selenium navigation, readiness, animation, and capture share one clock.""" + + mock_app_patch.config = { + "SCREENSHOT_LOCATE_WAIT": 10, + "SCREENSHOT_LOAD_WAIT": 60, + "SCREENSHOT_PAGE_LOAD_WAIT": 120, + "SCREENSHOT_SELENIUM_HEADSTART": 700, + "SCREENSHOT_SELENIUM_ANIMATION_WAIT": 700, + "SCREENSHOT_REPLACE_UNEXPECTED_ERRORS": False, + } + mock_driver = MagicMock() + mock_driver.execute_script.return_value = [ + {"chartId": "7", "state": "rendered"} + ] + element = MagicMock() + element.screenshot_as_png = b"screenshot" + mount_wait = MagicMock() + mount_wait.until.return_value = element + readiness_wait = MagicMock() + readiness_wait.until.return_value = True + mock_wait.side_effect = [mount_wait, readiness_wait] + context = ReportExecutionContext( + execution_id=UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524"), + report_schedule_id=11, + dashboard_id=805, + expected_chart_count=52, + deadline=ReportExecutionDeadline( + total_seconds=900, + started_at=0, + _clock=lambda: 100, + ), + capture_reserve_seconds=60, + delivery_reserve_seconds=120, + cleanup_reserve_seconds=30, + ) + screenshot = WebDriverSelenium(driver_type="chrome") + screenshot._driver = mock_driver + + assert ( + screenshot.get_screenshot( + "http://example.com/dashboard/805", + "standalone", + report_execution_context=context, + ) + == b"screenshot" + ) + + # 900 total - 100 elapsed - 210 reserved = 590 seconds. Selenium APIs + # take seconds (unlike Playwright's millisecond timeouts). + mock_driver.set_page_load_timeout.assert_called_once_with(590) + assert mock_wait.call_args_list == [ + call(mock_driver, 10), + call(mock_driver, 590), + ] + assert mock_sleep.call_args_list == [call(590), call(590)] + assert element.screenshot_as_png == b"screenshot" + class TestPlaywrightAvailabilityCheck: """Test comprehensive Playwright availability checking.""" @@ -1654,6 +1720,36 @@ def record_wait_for_timeout(ms): assert "animation_wait" in call_order assert call_order.index("spinner_wait") < call_order.index("animation_wait") + @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) + @patch("superset.utils.webdriver._browser_manager") + @patch("superset.utils.webdriver.take_tiled_screenshot") + @patch("superset.utils.webdriver.app") + def test_chart_threshold_does_not_tile_short_dashboard( + self, mock_app, mock_take_tiled, mock_browser_manager + ): + """Preserve the historical height guard for reports and thumbnails.""" + + mock_user = MagicMock() + mock_user.username = "test_user" + mock_app.config = { + **self._base_config, + "SCREENSHOT_TILED_ENABLED": True, + "SCREENSHOT_TILED_CHART_THRESHOLD": 20, + "SCREENSHOT_TILED_HEIGHT_THRESHOLD": 5000, + "SCREENSHOT_TILED_VIEWPORT_HEIGHT": 600, + } + mock_context, mock_page = self._make_pw_mocks(mock_browser_manager) + mock_page.evaluate.side_effect = [25, 500, [], []] + + with patch.object(WebDriverPlaywright, "auth", return_value=mock_context): + result = WebDriverPlaywright("chrome").get_screenshot( + "http://example.com", "test-element", mock_user + ) + + assert result == b"screenshot" + mock_take_tiled.assert_not_called() + mock_page.set_viewport_size.assert_not_called() + @patch("superset.utils.webdriver.PLAYWRIGHT_AVAILABLE", True) @patch("superset.utils.webdriver._browser_manager") @patch("superset.utils.webdriver.take_tiled_screenshot") From d81ef613da0be73cc4f485a551b92d1722f4d647 Mon Sep 17 00:00:00 2001 From: Matt Fitzgerald Date: Fri, 31 Jul 2026 06:19:31 +0000 Subject: [PATCH 06/19] fix(reports): terminalize failed captures --- superset/commands/report/execute.py | 130 +++++++++++++++++- .../reports/commands_tests.py | 92 +++++++++++++ .../commands/report/execute_test.py | 65 +++++++++ 3 files changed, 283 insertions(+), 4 deletions(-) diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 820bfa4acd2f..9c6b6cbf51a1 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -28,6 +28,7 @@ import pandas as pd from celery.exceptions import SoftTimeLimitExceeded from flask import current_app as app +from sqlalchemy.exc import SQLAlchemyError from superset import db, security_manager from superset.commands.base import BaseCommand @@ -157,6 +158,109 @@ def log_report_delivery_phase( ) +def persist_owned_report_execution_terminal_error( + report_schedule_id: int, + execution_id: UUID, + error_message: str, + terminal_reason: str, + report_context: ReportExecutionContext | None = None, +) -> bool: + """ + Terminalize this command's WORKING row from its application-owned boundary. + + Report states normally persist their terminal result before re-raising. If + that first write loses its transaction or database connection, the command + boundary is the last safe in-process retry: it still has Flask application + context and knows the execution UUID it owns. A compare against the latest + active WORKING row prevents an old worker from changing the schedule state + after a newer execution has started. + """ + + try: + # The state-machine transaction has already rolled back on its way to + # this boundary. Roll back again so a failed terminal flush cannot leave + # the scoped session unusable for the retry. + db.session.rollback() # pylint: disable=consider-using-transaction + working_log = ( + db.session.query(ReportExecutionLog) + .filter( + ReportExecutionLog.report_schedule_id == report_schedule_id, + ReportExecutionLog.uuid == execution_id, + ReportExecutionLog.state == ReportState.WORKING, + ReportExecutionLog.error_message.is_(None), + ) + .first() + ) + if working_log is None: + return False + + latest_working_log = ( + db.session.query(ReportExecutionLog) + .filter( + ReportExecutionLog.report_schedule_id == report_schedule_id, + ReportExecutionLog.state == ReportState.WORKING, + ReportExecutionLog.error_message.is_(None), + ) + .order_by(ReportExecutionLog.end_dttm.desc()) + .first() + ) + report_schedule = working_log.report_schedule + owns_schedule_state = ( + report_schedule.last_state == ReportState.WORKING + and latest_working_log is not None + and latest_working_log.uuid == execution_id + ) + ended_at = datetime.now(timezone.utc).replace(tzinfo=None) + working_log.state = ReportState.ERROR + working_log.error_message = error_message + working_log.end_dttm = ended_at + if owns_schedule_state: + report_schedule.last_state = ReportState.ERROR + report_schedule.last_eval_dttm = ended_at + + db.session.commit() # pylint: disable=consider-using-transaction + log_context = ( + report_context.log_context + if report_context is not None + else ( + f"capture_kind=report execution_id={execution_id} " + f"report_schedule_id={report_schedule_id} " + f"dashboard_id={report_schedule.dashboard_id} " + f"chart_id={report_schedule.chart_id}" + ) + ) + elapsed_seconds = ( + f"{report_context.deadline.elapsed_seconds:.2f}" + if report_context is not None + else "unknown" + ) + remaining_seconds = ( + f"{report_context.deadline.remaining_seconds:.2f}" + if report_context is not None + else "unknown" + ) + logger.info( + "report_execution_terminal %s state=%s terminal_reason=%s " + "elapsed_seconds=%s remaining_seconds=%s", + log_context, + ReportState.ERROR.value, + terminal_reason, + elapsed_seconds, + remaining_seconds, + ) + return True + except Exception: # noqa: BLE001 # never mask the report's original exception + db.session.rollback() # pylint: disable=consider-using-transaction + logger.exception( + "Failed terminal persistence retry for report execution " + "capture_kind=report execution_id=%s report_schedule_id=%s " + "terminal_reason=terminal_persistence_retry_failed", + execution_id, + report_schedule_id, + ) + return False + + class BaseReportState: current_states: list[ReportState] = [] initial: bool = False @@ -1422,9 +1526,10 @@ def next(self) -> None: # noqa: C901 self.update_report_schedule_and_log( ReportState.ERROR, error_message=error_message ) - except ReportScheduleUnexpectedError as logging_ex: + except (ReportScheduleUnexpectedError, SQLAlchemyError) as logging_ex: # Logging failed (likely StaleDataError), but we still want to # raise the original error so the root cause remains visible + db.session.rollback() # pylint: disable=consider-using-transaction logger.warning( "Failed to log error for report schedule (execution %s) " "due to database issue", @@ -1611,9 +1716,10 @@ def next(self) -> None: self.update_report_schedule_and_log( ReportState.ERROR, error_message=str(ex) ) - except ReportScheduleUnexpectedError as logging_ex: + except (ReportScheduleUnexpectedError, SQLAlchemyError) as logging_ex: # Logging failed (likely StaleDataError), but we still want to # raise the original error so the root cause remains visible + db.session.rollback() # pylint: disable=consider-using-transaction logger.warning( "Failed to log error for report schedule (execution %s) " "due to database issue", @@ -1676,12 +1782,12 @@ def __init__(self, task_id: str, model_id: int, scheduled_dttm: datetime): def run(self) -> None: monotonic_started_at = time.monotonic() + report_execution_context: ReportExecutionContext | None = None try: self.validate() if not self._model: raise ReportScheduleExecuteUnexpectedError() - report_execution_context = None if self._model.type == ReportScheduleType.REPORT: total_seconds = float( app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] @@ -1773,9 +1879,25 @@ def run(self) -> None: elapsed_seconds, self._execution_id, ) - except (CommandException, SoftTimeLimitExceeded): + except (CommandException, SoftTimeLimitExceeded) as ex: + if self._model and self._model.type == ReportScheduleType.REPORT: + persist_owned_report_execution_terminal_error( + self._model.id, + self._execution_id, + str(ex) or type(ex).__name__, + type(ex).__name__, + report_execution_context, + ) raise except Exception as ex: + if self._model and self._model.type == ReportScheduleType.REPORT: + persist_owned_report_execution_terminal_error( + self._model.id, + self._execution_id, + str(ex) or type(ex).__name__, + type(ex).__name__, + report_execution_context, + ) raise ReportScheduleUnexpectedError(str(ex)) from ex def validate(self) -> None: diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index 6ea428d984af..caf2c69e47d2 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -14,6 +14,7 @@ # KIND, either express or implied. See the License for the # specific language governing permissions and limitations # under the License. +import logging from collections.abc import Iterator from contextlib import contextmanager from datetime import datetime, timedelta, timezone @@ -35,6 +36,7 @@ SlackRequestError, SlackTokenRotationError, ) +from sqlalchemy.exc import OperationalError from sqlalchemy.sql import func, text try: @@ -86,6 +88,7 @@ from superset.utils import json from superset.utils.database import get_example_database from superset.utils.report_execution import ReportExecutionContext +from superset.utils.webdriver import PlaywrightTimeout from tests.integration_tests.fixtures.birth_names_dashboard import ( load_birth_names_dashboard_with_slices, # noqa: F401 load_birth_names_data, # noqa: F401 @@ -2408,6 +2411,95 @@ def test_fail_screenshot(screenshot_mock, email_mock, create_report_email_chart) ) +@pytest.mark.usefixtures( + "load_birth_names_dashboard_with_slices", "create_report_email_chart" +) +@patch("superset.reports.notifications.email.send_email_smtp") +@patch("superset.utils.screenshots.ChartScreenshot.get_screenshot") +def test_readiness_timeout_retries_terminal_persistence_and_allows_next_schedule( + screenshot_mock, + email_mock, + create_report_email_chart, + caplog, + monkeypatch, +): + """A failed first terminal write must not leave a timed-out report WORKING.""" + + original_update = BaseReportState.update_report_schedule_and_log + terminal_write_failed = False + + def fail_first_terminal_write( + state: BaseReportState, + report_state: ReportState, + error_message: Optional[str] = None, + ) -> None: + nonlocal terminal_write_failed + if report_state == ReportState.ERROR and not terminal_write_failed: + terminal_write_failed = True + raise OperationalError( + "UPDATE report_execution_log", + {}, + RuntimeError("connection lost before terminal commit"), + ) + original_update(state, report_state, error_message) + + monkeypatch.setattr( + BaseReportState, + "update_report_schedule_and_log", + fail_first_terminal_write, + ) + caplog.set_level(logging.INFO, logger="superset.commands.report.execute") + screenshot_mock.side_effect = PlaywrightTimeout( + "readiness allocation expired with 12/52 holders ready" + ) + create_report_email_chart.last_state = ReportState.SUCCESS + db.session.commit() + + with pytest.raises(ReportScheduleScreenshotFailedError): + AsyncExecuteReportScheduleCommand( + TEST_ID, + create_report_email_chart.id, + datetime.utcnow(), + ).run() + + assert terminal_write_failed + db.session.refresh(create_report_email_chart) + timed_out_log = ( + db.session.query(ReportExecutionLog) + .filter(ReportExecutionLog.uuid == UUID(TEST_ID)) + .one() + ) + assert timed_out_log.state == ReportState.ERROR + assert "readiness allocation expired" in timed_out_log.error_message + assert create_report_email_chart.last_state == ReportState.ERROR + email_mock.assert_not_called() + assert any( + "report_execution_terminal" in record.message + and TEST_ID in record.message + and "terminal_reason=ReportScheduleScreenshotFailedError" in record.message + for record in caplog.records + ) + + next_execution_id = str(uuid4()) + screenshot_mock.side_effect = None + screenshot_mock.return_value = SCREENSHOT_FILE + + AsyncExecuteReportScheduleCommand( + next_execution_id, + create_report_email_chart.id, + datetime.utcnow(), + ).run() + + db.session.refresh(create_report_email_chart) + next_log = ( + db.session.query(ReportExecutionLog) + .filter(ReportExecutionLog.uuid == UUID(next_execution_id)) + .one() + ) + assert next_log.state == ReportState.SUCCESS + assert create_report_email_chart.last_state == ReportState.SUCCESS + + @pytest.mark.usefixtures( "load_birth_names_dashboard_with_slices", "create_report_email_chart_with_csv" ) diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index a57c0b73cfd7..090ac56b51bb 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -43,6 +43,7 @@ ) from superset.commands.report.execute import ( BaseReportState, + persist_owned_report_execution_terminal_error, ReportNotTriggeredErrorState, ReportScheduleStateMachine, ReportSuccessState, @@ -2689,6 +2690,70 @@ def test_create_log_promotes_same_execution_working_row_without_duplicate( mock_db.session.commit.assert_called_once() +def test_terminal_persistence_retry_promotes_owned_working_execution( + mocker: MockerFixture, +) -> None: + execution_id = UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524") + schedule = mocker.Mock(spec=ReportSchedule) + schedule.last_state = ReportState.WORKING + schedule.dashboard_id = 805 + schedule.chart_id = None + working_log = mocker.Mock() + working_log.uuid = execution_id + working_log.report_schedule = schedule + + mock_db = mocker.patch("superset.commands.report.execute.db") + filtered_query = mock_db.session.query.return_value.filter.return_value + filtered_query.first.return_value = working_log + filtered_query.order_by.return_value.first.return_value = working_log + + assert persist_owned_report_execution_terminal_error( + 11, + execution_id, + "Failed taking a screenshot readiness allocation expired", + "ReportScheduleScreenshotFailedError", + ) + + assert working_log.state == ReportState.ERROR + assert ( + working_log.error_message + == "Failed taking a screenshot readiness allocation expired" + ) + assert schedule.last_state == ReportState.ERROR + mock_db.session.commit.assert_called_once() + + +def test_terminal_persistence_retry_does_not_overwrite_newer_execution( + mocker: MockerFixture, +) -> None: + execution_id = UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524") + schedule = mocker.Mock(spec=ReportSchedule) + schedule.last_state = ReportState.WORKING + schedule.dashboard_id = 805 + schedule.chart_id = None + working_log = mocker.Mock() + working_log.uuid = execution_id + working_log.report_schedule = schedule + newer_working_log = mocker.Mock() + newer_working_log.uuid = uuid4() + + mock_db = mocker.patch("superset.commands.report.execute.db") + filtered_query = mock_db.session.query.return_value.filter.return_value + filtered_query.first.return_value = working_log + filtered_query.order_by.return_value.first.return_value = newer_working_log + + assert persist_owned_report_execution_terminal_error( + 11, + execution_id, + "Failed taking a screenshot readiness allocation expired", + "ReportScheduleScreenshotFailedError", + ) + + assert working_log.state == ReportState.ERROR + assert schedule.last_state == ReportState.WORKING + mock_db.session.commit.assert_called_once() + + def test_success_state_report_sends_and_logs_success( mocker: MockerFixture, ) -> None: From f27092c928acd66d90b57ba505c4621264524295 Mon Sep 17 00:00:00 2001 From: Matt Fitzgerald Date: Fri, 31 Jul 2026 06:25:43 +0000 Subject: [PATCH 07/19] fix(reports): preserve active same-id replays --- superset/commands/report/execute.py | 6 +++- .../reports/commands_tests.py | 31 +++++++++++++++++++ 2 files changed, 36 insertions(+), 1 deletion(-) diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 9c6b6cbf51a1..9098e1f21379 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -1880,7 +1880,11 @@ def run(self) -> None: self._execution_id, ) except (CommandException, SoftTimeLimitExceeded) as ex: - if self._model and self._model.type == ReportScheduleType.REPORT: + if ( + self._model + and self._model.type == ReportScheduleType.REPORT + and not isinstance(ex, ReportSchedulePreviousWorkingError) + ): persist_owned_report_execution_terminal_error( self._model.id, self._execution_id, diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index caf2c69e47d2..8d6d9b240505 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -1934,6 +1934,37 @@ def test_report_schedule_working(create_report_slack_chart_working): assert create_report_slack_chart_working.last_state == ReportState.WORKING +@pytest.mark.usefixtures("create_report_slack_chart_working") +def test_report_schedule_same_execution_replay_stays_working( + create_report_slack_chart_working, +): + """A fresh replay must not terminalize the active execution it duplicates.""" + + active_log = ( + db.session.query(ReportExecutionLog) + .filter( + ReportExecutionLog.report_schedule == create_report_slack_chart_working, + ReportExecutionLog.state == ReportState.WORKING, + ReportExecutionLog.error_message.is_(None), + ) + .one() + ) + + with freeze_time("2020-01-01T00:00:00Z"): + with pytest.raises(ReportSchedulePreviousWorkingError): + AsyncExecuteReportScheduleCommand( + str(active_log.uuid), + create_report_slack_chart_working.id, + datetime.utcnow(), + ).run() + + db.session.refresh(active_log) + db.session.refresh(create_report_slack_chart_working) + assert active_log.state == ReportState.WORKING + assert active_log.error_message is None + assert create_report_slack_chart_working.last_state == ReportState.WORKING + + @pytest.mark.usefixtures("create_report_slack_chart_working") def test_report_schedule_working_timeout(create_report_slack_chart_working): """ From ac3f21ce4716f80adcd9d82f2b7cb03a5224a091 Mon Sep 17 00:00:00 2001 From: Matt Fitzgerald Date: Fri, 31 Jul 2026 06:29:38 +0000 Subject: [PATCH 08/19] fix(reports): scope terminal retry to row owner --- superset/commands/report/execute.py | 16 +++++- .../reports/commands_tests.py | 50 +++++++++++++++++++ 2 files changed, 64 insertions(+), 2 deletions(-) diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 9098e1f21379..948dc867ac9d 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -1783,12 +1783,20 @@ def __init__(self, task_id: str, model_id: int, scheduled_dttm: datetime): def run(self) -> None: monotonic_started_at = time.monotonic() report_execution_context: ReportExecutionContext | None = None + owns_report_working_state = False try: self.validate() if not self._model: raise ReportScheduleExecuteUnexpectedError() if self._model.type == ReportScheduleType.REPORT: + # An invocation that enters on WORKING is a duplicate or stale + # recovery, not the owner that created the active row. Its state + # handler may terminalize a stale execution, but the command + # boundary must never infer ownership from a replayed UUID. + owns_report_working_state = ( + self._model.last_state != ReportState.WORKING + ) total_seconds = float( app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] ) @@ -1883,7 +1891,7 @@ def run(self) -> None: if ( self._model and self._model.type == ReportScheduleType.REPORT - and not isinstance(ex, ReportSchedulePreviousWorkingError) + and owns_report_working_state ): persist_owned_report_execution_terminal_error( self._model.id, @@ -1894,7 +1902,11 @@ def run(self) -> None: ) raise except Exception as ex: - if self._model and self._model.type == ReportScheduleType.REPORT: + if ( + self._model + and self._model.type == ReportScheduleType.REPORT + and owns_report_working_state + ): persist_owned_report_execution_terminal_error( self._model.id, self._execution_id, diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index 8d6d9b240505..041bea016492 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -59,6 +59,7 @@ ReportScheduleScreenshotFailedError, ReportScheduleScreenshotTimeout, ReportScheduleSystemErrorsException, + ReportScheduleUnexpectedError, ReportScheduleWorkingTimeoutError, ) from superset.commands.report.execute import ( @@ -1965,6 +1966,55 @@ def test_report_schedule_same_execution_replay_stays_working( assert create_report_slack_chart_working.last_state == ReportState.WORKING +@pytest.mark.usefixtures("create_report_slack_chart_working") +def test_same_execution_replay_write_failure_does_not_claim_active_row( + create_report_slack_chart_working, + monkeypatch, +): + """A failed refusal write must not make a replay own the active row.""" + + active_log = ( + db.session.query(ReportExecutionLog) + .filter( + ReportExecutionLog.report_schedule == create_report_slack_chart_working, + ReportExecutionLog.state == ReportState.WORKING, + ReportExecutionLog.error_message.is_(None), + ) + .one() + ) + + def fail_refusal_write( + state: BaseReportState, + report_state: ReportState, + error_message: Optional[str] = None, + ) -> None: + raise OperationalError( + "INSERT report_execution_log", + {}, + RuntimeError("connection lost while refusing replay"), + ) + + monkeypatch.setattr( + BaseReportState, + "update_report_schedule_and_log", + fail_refusal_write, + ) + + with freeze_time("2020-01-01T00:00:00Z"): + with pytest.raises(ReportScheduleUnexpectedError): + AsyncExecuteReportScheduleCommand( + str(active_log.uuid), + create_report_slack_chart_working.id, + datetime.utcnow(), + ).run() + + db.session.refresh(active_log) + db.session.refresh(create_report_slack_chart_working) + assert active_log.state == ReportState.WORKING + assert active_log.error_message is None + assert create_report_slack_chart_working.last_state == ReportState.WORKING + + @pytest.mark.usefixtures("create_report_slack_chart_working") def test_report_schedule_working_timeout(create_report_slack_chart_working): """ From 4ae2324f3f06a1fa99476514dd5429c03a7febe4 Mon Sep 17 00:00:00 2001 From: Matt Fitzgerald Date: Fri, 31 Jul 2026 06:58:09 +0000 Subject: [PATCH 09/19] fix(reports): terminalize refused executions --- superset/commands/report/execute.py | 35 +++++++++++++--- .../reports/commands_tests.py | 42 +++++++++++++++++-- .../commands/report/execute_test.py | 7 ++-- 3 files changed, 71 insertions(+), 13 deletions(-) diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 948dc867ac9d..f5dbf4f872fd 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -402,7 +402,13 @@ def update_report_schedule_slack_v2(self) -> None: recipient.type = ReportRecipientType.SLACKV2 recipient.recipient_config_json = recipient_config_json - def create_log(self, error_message: Optional[str] = None) -> None: + def create_log( + self, + error_message: Optional[str] = None, + *, + log_state: ReportState | None = None, + reuse_working_log: bool = True, + ) -> None: """ Creates a Report execution log, uses the current computed last_value for Alerts @@ -415,13 +421,16 @@ def create_log(self, error_message: Optional[str] = None) -> None: for working-timeout detection), so promoting it in place keeps one row per execution ``uuid`` without losing that behavior. The intentional error-notification marker row is a terminal-to-terminal transition, so it is - still recorded as a distinct row. + still recorded as a distinct row. A refused duplicate also needs a distinct + terminal audit row without changing the active owner's schedule state; + ``log_state`` and ``reuse_working_log`` support that case. """ from sqlalchemy.orm.exc import StaleDataError try: # Reuse the in-flight WORKING trigger row for this execution, if any, # so a single execution surfaces as a single log entry. + effective_state = log_state or self._report_schedule.last_state log = ( db.session.query(ReportExecutionLog) .filter( @@ -430,7 +439,7 @@ def create_log(self, error_message: Optional[str] = None) -> None: ReportExecutionLog.error_message.is_(None), ) .first() - if self._report_schedule.last_state != ReportState.WORKING + if reuse_working_log and effective_state != ReportState.WORKING else None ) if log is None: @@ -444,7 +453,7 @@ def create_log(self, error_message: Optional[str] = None) -> None: log.end_dttm = datetime.now(timezone.utc).replace(tzinfo=None) log.value = self._report_schedule.last_value log.value_row_json = self._report_schedule.last_value_row_json - log.state = self._report_schedule.last_state + log.state = effective_state log.error_message = error_message db.session.commit() # pylint: disable=consider-using-transaction except StaleDataError as ex: @@ -1621,9 +1630,23 @@ def next(self) -> None: self._execution_id, ) exception_working = ReportSchedulePreviousWorkingError() - self.update_report_schedule_and_log( - ReportState.WORKING, + # This invocation is terminal even though the active owner's schedule + # must remain WORKING. Record a distinct ERROR audit row rather than + # accumulating another WORKING row or unblocking the active schedule. + self.create_log( error_message=str(exception_working), + log_state=ReportState.ERROR, + reuse_working_log=False, + ) + elapsed, remaining = self._budget_values() + logger.info( + "report_execution_terminal %s state=%s terminal_reason=%s " + "elapsed_seconds=%s remaining_seconds=%s", + self._log_context, + ReportState.ERROR.value, + type(exception_working).__name__, + f"{elapsed:.2f}" if elapsed is not None else None, + f"{remaining:.2f}" if remaining is not None else None, ) raise exception_working diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index 041bea016492..b6523248e69c 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -166,8 +166,8 @@ def assert_log(state: str, error_message: Optional[str] = None): logs = db.session.query(ReportExecutionLog).all() if state == ReportState.WORKING: - # A report that is already in the WORKING state logs an extra WORKING row - # for the refused re-computation, on top of the row seeded by the fixture. + # A refused invocation gets its own terminal ERROR audit row while the + # active owner's seeded row and schedule remain WORKING. assert len(logs) == 2 elif state == ReportState.ERROR: # On error we also send a notification, which is recorded as a separate @@ -192,6 +192,33 @@ def assert_log(state: str, error_message: Optional[str] = None): assert log.value_row_json is None +def assert_refused_execution_history(report_schedule: ReportSchedule) -> None: + """Assert a refusal is terminal without adding another active WORKING row.""" + + logs = ( + db.session.query(ReportExecutionLog) + .filter(ReportExecutionLog.report_schedule == report_schedule) + .all() + ) + active_logs = [ + log + for log in logs + if log.state == ReportState.WORKING and log.error_message is None + ] + refused_logs = [ + log + for log in logs + if log.state == ReportState.ERROR + and log.error_message == str(ReportSchedulePreviousWorkingError()) + ] + assert len(active_logs) == 1 + assert len(refused_logs) == 1 + refused_log = refused_logs[0] + assert refused_log.start_dttm is not None + assert refused_log.end_dttm is not None + assert refused_log.end_dttm >= refused_log.start_dttm + + @contextmanager def create_test_table_context(database: Database): with database.get_sqla_engine() as engine: @@ -1932,6 +1959,7 @@ def test_report_schedule_working(create_report_slack_chart_working): ReportState.WORKING, error_message=ReportSchedulePreviousWorkingError.message, ) + assert_refused_execution_history(create_report_slack_chart_working) assert create_report_slack_chart_working.last_state == ReportState.WORKING @@ -1963,6 +1991,7 @@ def test_report_schedule_same_execution_replay_stays_working( db.session.refresh(create_report_slack_chart_working) assert active_log.state == ReportState.WORKING assert active_log.error_message is None + assert_refused_execution_history(create_report_slack_chart_working) assert create_report_slack_chart_working.last_state == ReportState.WORKING @@ -1985,8 +2014,10 @@ def test_same_execution_replay_write_failure_does_not_claim_active_row( def fail_refusal_write( state: BaseReportState, - report_state: ReportState, error_message: Optional[str] = None, + *, + log_state: ReportState | None = None, + reuse_working_log: bool = True, ) -> None: raise OperationalError( "INSERT report_execution_log", @@ -1996,7 +2027,7 @@ def fail_refusal_write( monkeypatch.setattr( BaseReportState, - "update_report_schedule_and_log", + "create_log", fail_refusal_write, ) @@ -2552,6 +2583,9 @@ def fail_first_terminal_write( ) assert timed_out_log.state == ReportState.ERROR assert "readiness allocation expired" in timed_out_log.error_message + assert timed_out_log.start_dttm is not None + assert timed_out_log.end_dttm is not None + assert timed_out_log.end_dttm > timed_out_log.start_dttm assert create_report_email_chart.last_state == ReportState.ERROR email_mock.assert_not_called() assert any( diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index 090ac56b51bb..c579c5b966a4 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -2306,14 +2306,15 @@ def test_working_state_still_working_raises_previous_working( """Working state not yet timed out should raise PreviousWorkingError.""" state = _make_state_instance(mocker, ReportWorkingState) mocker.patch.object(state, "is_on_working_timeout", return_value=False) - mocker.patch.object(state, "update_report_schedule_and_log") + mocker.patch.object(state, "create_log") with pytest.raises(ReportSchedulePreviousWorkingError): state.next() - state.update_report_schedule_and_log.assert_called_once_with( # type: ignore[attr-defined] - ReportState.WORKING, + state.create_log.assert_called_once_with( # type: ignore[attr-defined] error_message=str(ReportSchedulePreviousWorkingError()), + log_state=ReportState.ERROR, + reuse_working_log=False, ) From 2b745d022dd1dcb239a295859460588c15d2437e Mon Sep 17 00:00:00 2001 From: Matt Fitzgerald Date: Fri, 31 Jul 2026 07:25:11 +0000 Subject: [PATCH 10/19] test(reports): allow metadata timestamp precision --- tests/integration_tests/reports/commands_tests.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tests/integration_tests/reports/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index b6523248e69c..9dcfbc1aff30 100644 --- a/tests/integration_tests/reports/commands_tests.py +++ b/tests/integration_tests/reports/commands_tests.py @@ -2585,7 +2585,8 @@ def fail_first_terminal_write( assert "readiness allocation expired" in timed_out_log.error_message assert timed_out_log.start_dttm is not None assert timed_out_log.end_dttm is not None - assert timed_out_log.end_dttm > timed_out_log.start_dttm + # MySQL's metadata schema can store these values with one-second precision. + assert timed_out_log.end_dttm >= timed_out_log.start_dttm assert create_report_email_chart.last_state == ReportState.ERROR email_mock.assert_not_called() assert any( From 4b1ec359f95efde60ab7a73a5948a528a5265c60 Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Fri, 31 Jul 2026 23:59:50 +0000 Subject: [PATCH 11/19] fix(reports): honor per-schedule working_timeout and preserve default runtime ceiling Two behavior-preserving adjustments to the execution-budget rollout so the upstream default changes as little existing behavior as possible: - Default ALERT_REPORTS_EXECUTION_BUDGET_SECONDS is now one hour, matching the historical effective ceiling (the ReportSchedule.working_timeout model default). Default installations keep today's maximum report runtime and gain only the clean-failure/readiness semantics; deployments with tighter SLAs lower the value. - The effective budget for a REPORT schedule is min(ALERT_REPORTS_EXECUTION_BUDGET_SECONDS, working_timeout), centralized in resolve_report_execution_budget_seconds() and used consistently by the Celery limit derivation, the execution deadline construction, and stale- WORKING detection (which previously implemented its own inline min). The per-schedule working_timeout field keeps its historical user-facing meaning as a cap instead of being silently ignored for reports. A working_timeout below the summed phase reserves is floored at the minimum viable budget (reserves + 30s working allowance) with a warning, so such schedules fail cleanly at their first phase check instead of erroring while constructing the execution context. Also adds the UPDATING.md entry for the semantics change and documents the infrastructure sizing rules (pod termination grace vs budget + hard grace; web-server per-request timeout bounds single chart requests, not the report). Co-Authored-By: Claude --- UPDATING.md | 28 ++++++++++ .../configuration/alerts-reports.mdx | 22 ++++++-- superset/commands/report/execute.py | 19 ++++--- superset/config.py | 13 +++-- superset/utils/report_execution.py | 55 ++++++++++++++++++- .../commands/report/execute_test.py | 14 ++++- .../unit_tests/utils/test_report_execution.py | 44 +++++++++++++++ 7 files changed, 176 insertions(+), 19 deletions(-) diff --git a/UPDATING.md b/UPDATING.md index 75300f245686..580378d49f2e 100644 --- a/UPDATING.md +++ b/UPDATING.md @@ -24,6 +24,34 @@ assists people when migrating to a new version. ## Next +### Scheduled report execution now enforces one application deadline + +Scheduled report (not alert) executions are now governed by a single +end-to-end deadline shared by browser readiness, capture/PDF generation, +notification delivery, and terminal-state persistence, configured via +`ALERT_REPORTS_EXECUTION_BUDGET_SECONDS` (with per-phase reserve settings). +Behavior changes to be aware of: + +- The effective budget for a schedule is + `min(ALERT_REPORTS_EXECUTION_BUDGET_SECONDS, working_timeout)`. The default + budget (one hour) matches the historical `working_timeout` model default, + so default installations see no change in how long a report may run — + but reports now fail cleanly (with an error notification) at the deadline + instead of being killed silently by Celery. +- For REPORT schedules, the Celery `soft_time_limit`/`time_limit` are now + derived from that same effective budget plus + `ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS`, replacing the + previous `working_timeout + ALERT_REPORTS_WORKING_TIME_OUT_LAG` / + `+ ALERT_REPORTS_WORKING_SOFT_TIME_OUT_LAG` derivation. Alert schedules + keep the previous behavior. +- A `working_timeout` smaller than the summed phase reserves is floored at + the minimum viable budget (reserves + 30s) with a warning; such reports + fail fast at the first phase check rather than erroring at setup. +- Dashboard reports whose charts have not mounted are no longer captured + blank: readiness is polled until the deadline, and the report fails loudly + if charts never mount. Thumbnails and non-report screenshots keep their + previous behavior. + ### Principal listing APIs now honour related-field filters Two authorization-related listing behaviors changed for API clients. Neither diff --git a/docs/admin_docs/configuration/alerts-reports.mdx b/docs/admin_docs/configuration/alerts-reports.mdx index 3aa1af49acf6..6bcbe49a47e7 100644 --- a/docs/admin_docs/configuration/alerts-reports.mdx +++ b/docs/admin_docs/configuration/alerts-reports.mdx @@ -244,10 +244,13 @@ class CeleryConfig: } CELERY_CONFIG = CeleryConfig -# Scheduled reports share one 15-minute deadline across browser readiness, -# capture/PDF generation, delivery, and terminal-state persistence. Increase -# this only when the complete report pipeline is expected to take longer. -ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = 900 +# Scheduled reports share one deadline across browser readiness, capture/PDF +# generation, delivery, and terminal-state persistence. The effective budget +# for a schedule is min(this value, the schedule's working_timeout), so the +# per-schedule field keeps its meaning as a user-facing cap. The default (one +# hour) matches the historical working_timeout default, so upgrading changes +# no default behavior; lower it to enforce a tighter report SLA. +ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = 3600 # These reserves are part of (not additions to) the total budget and their sum # must be less than it. Readiness polling stops in time to leave capacity for @@ -271,6 +274,17 @@ ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS = 30 # Celery limits provide the final preemption boundary when the worker pool # supports them; PDF construction is checked immediately before and after the # synchronous builder but cannot be interrupted inside that call. +# +# Sizing the budget against infrastructure limits: +# - Kubernetes (or similar) pod termination grace must exceed +# budget + hard-timeout grace, or in-flight reports are killed mid-run on +# every deploy/node drain despite the application deadline. +# - The web server's per-request timeout (e.g. gunicorn ``timeout``) bounds +# each individual chart data request made by the headless browser -- not +# the report as a whole. Readiness allowance beyond that per-request +# ceiling buys nothing for a single slow chart (its request dies at the +# web layer and the chart reaches an error state), but multi-chart and +# tiled captures legitimately accumulate total time well past it. # Screenshot-specific waits continue to apply to thumbnails and other # standalone screenshot calls. Scheduled reports derive their waits from the diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index f5dbf4f872fd..04d1bee5dc3e 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -95,6 +95,7 @@ ReportExecutionBudgetExceededError, ReportExecutionContext, ReportExecutionDeadline, + resolve_report_execution_budget_seconds, ) from superset.utils.screenshots import ChartScreenshot, DashboardScreenshot from superset.utils.slack import get_channels_with_search, SlackChannelTypes @@ -1460,11 +1461,14 @@ def is_on_working_timeout(self) -> bool: return False working_timeout = self._report_schedule.working_timeout if self._report_schedule.type == ReportScheduleType.REPORT: - execution_budget = app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] - working_timeout = ( - min(working_timeout, execution_budget) - if working_timeout is not None - else execution_budget + # Same effective budget the execution enforces (global budget + # capped by the schedule's working_timeout, floored at the phase + # reserves), so stale detection and enforcement share one number. + working_timeout = int( + resolve_report_execution_budget_seconds( + app.config, + working_timeout=working_timeout, + ) ) return ( working_timeout is not None @@ -1820,8 +1824,9 @@ def run(self) -> None: owns_report_working_state = ( self._model.last_state != ReportState.WORKING ) - total_seconds = float( - app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] + total_seconds = resolve_report_execution_budget_seconds( + app.config, + working_timeout=self._model.working_timeout, ) deadline = ReportExecutionDeadline( total_seconds=total_seconds, diff --git a/superset/config.py b/superset/config.py index 36b5de5c3ff0..b5aa6ffc7b04 100644 --- a/superset/config.py +++ b/superset/config.py @@ -2445,10 +2445,15 @@ def EMAIL_HEADER_MUTATOR( # pylint: disable=invalid-name,unused-argument # noq ALERT_REPORTS_DEFAULT_WORKING_TIMEOUT = 3600 # End-to-end wall-clock budget for a scheduled report execution. A single # monotonic deadline derived from this value is shared by browser setup, -# readiness, capture/PDF generation, and notification delivery. Alerts retain -# their per-schedule ``working_timeout`` behavior because query evaluation and -# grace handling have different runtime characteristics. -ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = int(timedelta(minutes=15).total_seconds()) +# readiness, capture/PDF generation, and notification delivery. The effective +# budget for a given schedule is min(this value, the schedule's +# working_timeout), so the per-schedule field keeps its historical meaning as +# a user-facing cap. The default matches the historical effective ceiling +# (the working_timeout model default of one hour), so upgrading changes no +# default behavior; deployments with tighter SLAs should lower it. Alerts +# retain their per-schedule ``working_timeout`` + lag behavior because query +# evaluation and grace handling have different runtime characteristics. +ALERT_REPORTS_EXECUTION_BUDGET_SECONDS = int(timedelta(hours=1).total_seconds()) # Capacity inside the execution budget reserved from chart-readiness polling # for image capture/PDF construction, notification delivery, and the terminal # execution-log transition, respectively. Their sum must be less than the total; diff --git a/superset/utils/report_execution.py b/superset/utils/report_execution.py index 71630451166e..b18c0fbe23ce 100644 --- a/superset/utils/report_execution.py +++ b/superset/utils/report_execution.py @@ -18,12 +18,22 @@ from __future__ import annotations +import logging import time from collections.abc import Callable, Mapping from dataclasses import dataclass, field from typing import Any from uuid import UUID +logger = logging.getLogger(__name__) + +# Minimum working allowance kept above the summed phase reserves when a +# per-schedule working_timeout would otherwise squeeze the effective budget +# below what the execution context can represent. A floored budget still +# fails fast (budget-exceeded on the first phase) rather than erroring while +# constructing the deadline. +MIN_REPORT_EXECUTION_WORK_SECONDS = 30.0 + def validate_report_execution_config(config: Mapping[str, Any]) -> None: """Validate the scheduled-report budget invariant during application startup.""" @@ -50,6 +60,44 @@ def validate_report_execution_config(config: Mapping[str, Any]) -> None: raise ValueError("Report execution hard-timeout grace cannot be negative") +def resolve_report_execution_budget_seconds( + config: Mapping[str, Any], + working_timeout: int | None = None, +) -> float: + """Return the effective execution budget for one REPORT schedule. + + The per-schedule ``working_timeout`` keeps its historical, user-facing + meaning ("kill my report after N seconds"): when it is lower than the + global ``ALERT_REPORTS_EXECUTION_BUDGET_SECONDS`` it caps the budget, so + introducing the global deadline does not silently grant a schedule more + time than its owner configured. The result is floored at the summed + phase reserves plus a minimal working allowance so the execution context + remains constructible; a floored budget fails cleanly on its first phase + check instead of raising at setup. + """ + budget = float(config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"]) + if working_timeout is not None: + budget = min(budget, float(working_timeout)) + reserves_total = ( + float(config["ALERT_REPORTS_EXECUTION_CAPTURE_RESERVE_SECONDS"]) + + float(config["ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS"]) + + float(config["ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS"]) + ) + min_viable = reserves_total + MIN_REPORT_EXECUTION_WORK_SECONDS + if budget < min_viable: + logger.warning( + "Report working_timeout=%s is below the minimum viable execution " + "budget (%.0fs phase reserves + %.0fs working allowance); " + "flooring the effective budget at %.0fs.", + working_timeout, + reserves_total, + MIN_REPORT_EXECUTION_WORK_SECONDS, + min_viable, + ) + return min_viable + return budget + + class ReportExecutionBudgetExceededError(TimeoutError): """Raised before a report phase would overrun its execution deadline.""" @@ -201,7 +249,12 @@ def get_report_task_timeout_options( if not config["ALERT_REPORTS_WORKING_TIME_OUT_KILL"]: return {} if is_report: - budget = int(config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"]) + budget = int( + resolve_report_execution_budget_seconds( + config, + working_timeout=working_timeout, + ) + ) hard_grace = int(config["ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS"]) return { "soft_time_limit": budget, diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index c579c5b966a4..a2efaff80b0b 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -2387,7 +2387,12 @@ def test_report_working_state_recovery_is_bounded_by_execution_budget( app: SupersetApp, mocker: MockerFixture, ) -> None: - """A lost report worker cannot leave WORKING blocked for its legacy hour.""" + """A lost report worker is unblocked once the effective budget elapses. + + The effective budget is min(global budget, working_timeout); with a + deployment-tightened 900s budget, a schedule whose working_timeout is + still the one-hour default stops blocking after 15 minutes, not 60. + """ state = _make_state_instance( mocker, ReportWorkingState, @@ -2402,8 +2407,11 @@ def test_report_working_state_recovery_is_bounded_by_execution_budget( return_value=working_log, ) - assert app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] == 900 - assert state.is_on_working_timeout() + app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] = 900 + try: + assert state.is_on_working_timeout() + finally: + app.config["ALERT_REPORTS_EXECUTION_BUDGET_SECONDS"] = 3600 def test_soft_timeout_transitions_report_out_of_working( diff --git a/tests/unit_tests/utils/test_report_execution.py b/tests/unit_tests/utils/test_report_execution.py index 5545bbf6e6c2..6c99d53482d8 100644 --- a/tests/unit_tests/utils/test_report_execution.py +++ b/tests/unit_tests/utils/test_report_execution.py @@ -20,9 +20,11 @@ from superset.utils.report_execution import ( get_report_task_timeout_options, + MIN_REPORT_EXECUTION_WORK_SECONDS, ReportExecutionBudgetExceededError, ReportExecutionContext, ReportExecutionDeadline, + resolve_report_execution_budget_seconds, validate_report_execution_config, ) @@ -135,6 +137,48 @@ def test_report_task_limits_align_soft_timeout_with_budget() -> None: ) == {"soft_time_limit": 3601, "time_limit": 3610} +def test_working_timeout_caps_report_budget() -> None: + """A per-schedule working_timeout below the global budget keeps its + historical user-facing meaning: it caps the effective budget and the + derived Celery limits.""" + config = _report_config() + + assert resolve_report_execution_budget_seconds(config, working_timeout=600) == 600.0 + assert get_report_task_timeout_options( + is_report=True, + working_timeout=600, + config=config, + ) == {"soft_time_limit": 600, "time_limit": 630} + + +def test_working_timeout_above_budget_does_not_raise_it() -> None: + config = _report_config() + + assert ( + resolve_report_execution_budget_seconds(config, working_timeout=7200) == 900.0 + ) + + +def test_missing_working_timeout_uses_global_budget() -> None: + config = _report_config() + + assert ( + resolve_report_execution_budget_seconds(config, working_timeout=None) == 900.0 + ) + + +def test_tiny_working_timeout_floors_at_minimum_viable_budget() -> None: + """A working_timeout below the summed phase reserves cannot construct a + valid execution context; it is floored (with a warning) so the report + fails cleanly at its first phase check instead of erroring at setup.""" + config = _report_config() + reserves_total = 60 + 120 + 30 + + budget = resolve_report_execution_budget_seconds(config, working_timeout=120) + + assert budget == reserves_total + MIN_REPORT_EXECUTION_WORK_SECONDS + + @pytest.mark.parametrize( ("overrides", "message"), [ From b2e093758bc7effa1a1bf55fdead057612ecf629 Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Sat, 1 Aug 2026 00:11:45 +0000 Subject: [PATCH 12/19] fix(reports): anchor non-report tiled budget clock at overall screenshot start Folds open PR #42661 into this branch (its standalone form patched code this branch restructures): take_tiled_screenshot() accepts the caller's screenshot_started_at so navigation/headstart/element-wait time counts against the non-report task budget, matching the clock _wait_for_charts_ready already uses. Report captures are unaffected -- their deadline starts at task start, which supersedes the anchor. Falls back to "now" when omitted. Co-Authored-By: Claude --- superset/utils/screenshot_utils.py | 10 +++- superset/utils/webdriver.py | 1 + .../unit_tests/utils/test_screenshot_utils.py | 54 +++++++++++++++++++ tests/unit_tests/utils/webdriver_test.py | 3 +- 4 files changed, 66 insertions(+), 2 deletions(-) diff --git a/superset/utils/screenshot_utils.py b/superset/utils/screenshot_utils.py index 85fad3fef8f6..a65c39f81194 100644 --- a/superset/utils/screenshot_utils.py +++ b/superset/utils/screenshot_utils.py @@ -302,6 +302,7 @@ def take_tiled_screenshot( # noqa: C901 log_context: str | None = None, report_execution_context: ReportExecutionContext | None = None, url: str | None = None, + screenshot_started_at: float | None = None, ) -> bytes | None: """ Take a tiled screenshot of a large dashboard by scrolling and capturing sections. @@ -318,6 +319,12 @@ def take_tiled_screenshot( # noqa: C901 report_execution_context: Shared report identifiers, phase reserves, and end-to-end deadline. Thumbnail callers leave this unset. url: Dashboard URL included in structured capture logs. + screenshot_started_at: Optional time.monotonic() timestamp taken at + the start of the overall screenshot operation (before browser + navigation), so pre-capture time counts against the non-report + task budget -- the same clock _wait_for_charts_ready uses. + Ignored when a report_execution_context provides its own + deadline; falls back to "now" when omitted. Returns: Combined screenshot bytes or None if failed @@ -341,7 +348,8 @@ def take_tiled_screenshot( # noqa: C901 # match `except PlaywrightTimeout` and incorrectly propagate instead of # degrading to `None` like every other unexpected error in this function. readiness_timeout = False - screenshot_started_at = time.monotonic() + if screenshot_started_at is None: + screenshot_started_at = time.monotonic() task_budget = ( None if report_execution_context diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index a86d8a335517..a09d79e84519 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -769,6 +769,7 @@ def get_screenshot( # pylint: disable=too-many-locals, too-many-statements # n log_context=log_context, report_execution_context=report_execution_context, url=url, + screenshot_started_at=screenshot_started_at, ) if not img: # _get_screenshot() has no wait/readiness logic at diff --git a/tests/unit_tests/utils/test_screenshot_utils.py b/tests/unit_tests/utils/test_screenshot_utils.py index 8c1edd1436bf..1e5c602cc8a0 100644 --- a/tests/unit_tests/utils/test_screenshot_utils.py +++ b/tests/unit_tests/utils/test_screenshot_utils.py @@ -1028,6 +1028,60 @@ def test_no_celery_context_uses_fixed_total_fallback(self, mock_page): first_timeout = mock_page.wait_for_function.call_args_list[0][1]["timeout"] assert first_timeout == TILED_SCREENSHOT_TOTAL_WAIT_BUDGET_SECONDS * 1000 + def test_screenshot_started_at_counts_pre_capture_time_against_budget( + self, mock_page, monkeypatch + ): + """Time spent before tiling (navigation, headstart, element waits) + counts against the non-report budget when the caller provides the + overall screenshot start time -- the same clock the non-tiled + readiness wait uses. Report captures use their deadline instead.""" + monkeypatch.setattr( + "superset.utils.screenshot_utils.TILED_SCREENSHOT_TOTAL_WAIT_BUDGET_SECONDS", # noqa: E501 + 1000, + ) + clock = self._FakeClock() + # The overall screenshot started 900s ago; only 100s of budget remains. + clock.now = 900.0 + + with patch("superset.utils.screenshot_utils.current_task", None): + with patch("superset.utils.screenshot_utils.time.monotonic", new=clock): + with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): + take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + load_wait=500, + screenshot_started_at=0.0, + ) + + first_timeout = mock_page.wait_for_function.call_args_list[0][1]["timeout"] + assert first_timeout == 100 * 1000 + + def test_omitted_screenshot_started_at_anchors_clock_locally( + self, mock_page, monkeypatch + ): + """Without the caller-provided anchor the clock starts at entry + (backward-compatible default).""" + monkeypatch.setattr( + "superset.utils.screenshot_utils.TILED_SCREENSHOT_TOTAL_WAIT_BUDGET_SECONDS", # noqa: E501 + 1000, + ) + clock = self._FakeClock() + clock.now = 900.0 + + with patch("superset.utils.screenshot_utils.current_task", None): + with patch("superset.utils.screenshot_utils.time.monotonic", new=clock): + with patch("superset.utils.screenshot_utils.combine_screenshot_tiles"): + take_tiled_screenshot( + mock_page, + "dashboard", + tile_height=2000, + load_wait=500, + ) + + first_timeout = mock_page.wait_for_function.call_args_list[0][1]["timeout"] + assert first_timeout == 500 * 1000 + def test_derived_task_budget_caps_tile_wait(self, mock_page): """Inside Celery, the tiled path caps waits using the same task-derived budget as the non-tiled path (helper reuse, #42427).""" diff --git a/tests/unit_tests/utils/webdriver_test.py b/tests/unit_tests/utils/webdriver_test.py index 9a9888938228..fc18687f2434 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -15,7 +15,7 @@ # specific language governing permissions and limitations # under the License. -from unittest.mock import call, MagicMock, patch, PropertyMock +from unittest.mock import ANY, call, MagicMock, patch, PropertyMock from uuid import UUID import pytest @@ -1969,6 +1969,7 @@ def test_tiled_path_passes_animation_wait_per_tile_no_global_wait( log_context=None, report_execution_context=None, url="http://example.com", + screenshot_started_at=ANY, ) # 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) From 9b84ce711b1fab57fce158665a0f189cede2672a Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Sat, 1 Aug 2026 00:52:33 +0000 Subject: [PATCH 13/19] test(reports): align scheduler budget test with the 3600s default The integration test still asserted the 900s draft default. The default budget now resolves to min(3600, working_timeout default 3600) = 3600 with a 30s hard grace; the 900/930 expectation is kept by explicitly setting working_timeout=900, which also exercises the capping path end to end through the scheduler. Co-Authored-By: Claude --- tests/integration_tests/reports/scheduler_tests.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/tests/integration_tests/reports/scheduler_tests.py b/tests/integration_tests/reports/scheduler_tests.py index 60d958cba180..27243fdc5038 100644 --- a/tests/integration_tests/reports/scheduler_tests.py +++ b/tests/integration_tests/reports/scheduler_tests.py @@ -119,10 +119,22 @@ def test_scheduler_report_timeout_uses_end_to_end_budget(execute_mock, editors): editors=editors, ) + # The default budget (1h) matches the working_timeout column default, so + # the derived limits preserve the historical runtime ceiling out of the box. + with freeze_time("2020-01-01T09:00:00Z"): + scheduler() + assert execute_mock.call_args[1]["soft_time_limit"] == 3600 + assert execute_mock.call_args[1]["time_limit"] == 3630 + + # A lower per-schedule working_timeout caps the effective budget and the + # derived Celery limits. + report_schedule.working_timeout = 900 + db.session.commit() with freeze_time("2020-01-01T09:00:00Z"): scheduler() assert execute_mock.call_args[1]["soft_time_limit"] == 900 assert execute_mock.call_args[1]["time_limit"] == 930 + db.session.delete(report_schedule) db.session.commit() From d06a3b55d28df561213928d8ab4244d112e3bfc5 Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Sat, 1 Aug 2026 01:01:36 +0000 Subject: [PATCH 14/19] test(reports): cover the shared soft-timeout handler for alerts The SoftTimeLimitExceeded handler in reports.execute is deliberately type-unconditional; this pins the alert path (metric, warning log, explicit FAILURE, re-raise) that the PR body describes as observability-only for alerts. Co-Authored-By: Claude --- .../tasks/test_scheduler_soft_timeout.py | 68 +++++++++++++++++++ 1 file changed, 68 insertions(+) create mode 100644 tests/unit_tests/tasks/test_scheduler_soft_timeout.py diff --git a/tests/unit_tests/tasks/test_scheduler_soft_timeout.py b/tests/unit_tests/tasks/test_scheduler_soft_timeout.py new file mode 100644 index 000000000000..6eb0a80e7760 --- /dev/null +++ b/tests/unit_tests/tasks/test_scheduler_soft_timeout.py @@ -0,0 +1,68 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, +# software distributed under the License is distributed on an +# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +# KIND, either express or implied. See the License for the +# specific language governing permissions and limitations +# under the License. +"""Unit tests for the shared ``reports.execute`` soft-timeout handler.""" + +from unittest.mock import MagicMock, patch + +import pytest +from celery.exceptions import SoftTimeLimitExceeded + + +def test_soft_timeout_handler_is_shared_by_alerts() -> None: + """The ``reports.execute`` soft-timeout handler is type-unconditional. + + The handler runs before any report-vs-alert dispatch, so an ALERT + schedule that hits ``SoftTimeLimitExceeded`` gets the same operator + metric, warning log, and explicit FAILURE state before the re-raise as + a report does. This is observability-only for alerts: their numeric + Celery limits are untouched, and pre-handler behavior (uncaught + exception, Celery FAILURE) is preserved by the re-raise. + """ + from superset.tasks.scheduler import execute + + alert_schedule_id = 1234 + stats_logger = MagicMock() + + # The task reads STATS_LOGGER via the module's ``current_app`` proxy; + # patching the proxy keeps the test independent of which Flask app the + # Celery AppContextTask wrapper happens to have captured. + with ( + patch("superset.tasks.scheduler.current_app") as current_app_mock, + patch( + "superset.commands.report.execute." + "AsyncExecuteReportScheduleCommand.__init__", + return_value=None, + ), + patch( + "superset.commands.report.execute.AsyncExecuteReportScheduleCommand.run", + side_effect=SoftTimeLimitExceeded(), + ), + patch("superset.tasks.scheduler.execute.update_state") as update_state_mock, + patch("superset.tasks.scheduler.logger") as logger_mock, + ): + current_app_mock.config = {"STATS_LOGGER": stats_logger} + with pytest.raises(SoftTimeLimitExceeded): + execute(alert_schedule_id) + + stats_logger.incr.assert_any_call("reports.execute.celery_soft_timeout") + update_state_mock.assert_called_once_with(state="FAILURE") + assert any( + call.args + and "terminal_reason=celery_soft_timeout" in call.args[0] + and alert_schedule_id in call.args + for call in logger_mock.warning.call_args_list + ) From 8feae1a1f0721ad03287f01bfe9e0a2af82a7687 Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Sat, 1 Aug 2026 01:39:26 +0000 Subject: [PATCH 15/19] fix(ci): auto-walrus compliance, test persistence, and review-suggested renames - Apply auto-walrus rewrite in resolve_report_execution_budget_seconds (pre-commit hook failure on CI). - Persist the working_timeout override in the scheduler budget test via a query-level UPDATE: the attribute write on the fixture object was not flushed in CI (all three DB backends still derived limits from 3600), so phase two asserted against the default. - Rename the two delegation-only unit tests to reflect what they assert (they mock update_report_schedule_and_log; the real promotion path is covered by integration tests), per review feedback. Co-Authored-By: Claude --- superset/utils/report_execution.py | 3 +-- tests/integration_tests/reports/scheduler_tests.py | 9 ++++++--- tests/unit_tests/commands/report/execute_test.py | 4 ++-- 3 files changed, 9 insertions(+), 7 deletions(-) diff --git a/superset/utils/report_execution.py b/superset/utils/report_execution.py index b18c0fbe23ce..690dfcaa454a 100644 --- a/superset/utils/report_execution.py +++ b/superset/utils/report_execution.py @@ -83,8 +83,7 @@ def resolve_report_execution_budget_seconds( + float(config["ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS"]) + float(config["ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS"]) ) - min_viable = reserves_total + MIN_REPORT_EXECUTION_WORK_SECONDS - if budget < min_viable: + if budget < (min_viable := reserves_total + MIN_REPORT_EXECUTION_WORK_SECONDS): logger.warning( "Report working_timeout=%s is below the minimum viable execution " "budget (%.0fs phase reserves + %.0fs working allowance); " diff --git a/tests/integration_tests/reports/scheduler_tests.py b/tests/integration_tests/reports/scheduler_tests.py index 27243fdc5038..d7a625871377 100644 --- a/tests/integration_tests/reports/scheduler_tests.py +++ b/tests/integration_tests/reports/scheduler_tests.py @@ -23,7 +23,7 @@ from freezegun.api import FakeDatetime from superset.extensions import db -from superset.reports.models import ReportScheduleType +from superset.reports.models import ReportSchedule, ReportScheduleType from superset.subjects.models import Subject from superset.subjects.types import SubjectType from superset.tasks.scheduler import execute, log_task_failure, scheduler @@ -127,8 +127,11 @@ def test_scheduler_report_timeout_uses_end_to_end_budget(execute_mock, editors): assert execute_mock.call_args[1]["time_limit"] == 3630 # A lower per-schedule working_timeout caps the effective budget and the - # derived Celery limits. - report_schedule.working_timeout = 900 + # derived Celery limits. Update via query so persistence does not depend + # on which session the fixture object is bound to. + db.session.query(ReportSchedule).filter( + ReportSchedule.id == report_schedule.id + ).update({"working_timeout": 900}) db.session.commit() with freeze_time("2020-01-01T09:00:00Z"): scheduler() diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index a2efaff80b0b..1519c21063ad 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -2318,7 +2318,7 @@ def test_working_state_still_working_raises_previous_working( ) -def test_working_timeout_replay_promotes_original_execution_without_duplicate_log( +def test_working_timeout_replay_delegates_single_terminal_update( mocker: MockerFixture, ) -> None: state = _make_state_instance( @@ -2348,7 +2348,7 @@ def test_working_timeout_replay_promotes_original_execution_without_duplicate_lo assert working_log.state == ReportState.WORKING -def test_new_report_execution_does_not_deliver_during_stale_recovery( +def test_stale_recovery_delegates_terminal_update_without_delivery( mocker: MockerFixture, ) -> None: """Recovery unblocks the schedule without racing the old worker's audit row.""" From ba7777d94a8ef908b32fb60d14f29a535326d9a1 Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Sat, 1 Aug 2026 02:15:59 +0000 Subject: [PATCH 16/19] docs(reports): remove stale 15-minute soft-limit reference The hard-timeout grace comment predated the 3600s default; the soft limit is the resolved execution budget, not a fixed 15 minutes. Co-Authored-By: Claude --- docs/admin_docs/configuration/alerts-reports.mdx | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/docs/admin_docs/configuration/alerts-reports.mdx b/docs/admin_docs/configuration/alerts-reports.mdx index 6bcbe49a47e7..1f46cebe1dfa 100644 --- a/docs/admin_docs/configuration/alerts-reports.mdx +++ b/docs/admin_docs/configuration/alerts-reports.mdx @@ -260,8 +260,10 @@ ALERT_REPORTS_EXECUTION_DELIVERY_RESERVE_SECONDS = 120 ALERT_REPORTS_EXECUTION_CLEANUP_RESERVE_SECONDS = 30 # Celery's hard limit leaves this additional window for terminal cleanup after -# the 15-minute soft limit. ALERT_REPORTS_WORKING_TIME_OUT_KILL controls these -# Celery limits; disabling it does not disable the application deadline above. +# the soft limit, which equals the resolved execution budget (the configured +# budget capped by each schedule's working_timeout). +# ALERT_REPORTS_WORKING_TIME_OUT_KILL controls these Celery limits; disabling +# it does not disable the application deadline above. ALERT_REPORTS_EXECUTION_HARD_TIMEOUT_GRACE_SECONDS = 30 # Invalid budget/reserve combinations fail application startup instead of From 7e2010fe0da0a88507d8410fd0c85a6b79f16224 Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Sat, 1 Aug 2026 02:44:44 +0000 Subject: [PATCH 17/19] test(reports): cover delivery-phase gate and retry-net failure path; drop dead guards Per bot review feedback: - log_report_delivery_phase: no-op without a report context, raises on exhausted budget when enforcing, and still logs post-send phases without raising when enforcement is off. - persist_owned_report_execution_terminal_error: a DB failure inside the retry itself rolls back, logs, and returns False without masking the report's original exception. - Remove two always-true 'if deadline' guards in the Selenium readiness logging (deadline is assigned unconditionally and always truthy). Co-Authored-By: Claude --- superset/utils/webdriver.py | 8 +- .../commands/report/execute_test.py | 84 +++++++++++++++++++ 2 files changed, 88 insertions(+), 4 deletions(-) diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index a09d79e84519..19bad3a0a549 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -1310,8 +1310,8 @@ def phase_timeout( holder.get("state") in ready_states for holder in holder_states ), - (f"{deadline.elapsed_seconds:.2f}" if deadline else None), - (f"{deadline.remaining_seconds:.2f}" if deadline else None), + f"{deadline.elapsed_seconds:.2f}", + f"{deadline.remaining_seconds:.2f}", f" [{log_context}]" if log_context else "", ) except TimeoutException: @@ -1342,8 +1342,8 @@ def phase_timeout( report_execution_context.expected_chart_count, len(holder_states), ready_holders, - (f"{deadline.elapsed_seconds:.2f}" if deadline else None), - (f"{deadline.remaining_seconds:.2f}" if deadline else None), + f"{deadline.elapsed_seconds:.2f}", + f"{deadline.remaining_seconds:.2f}", readiness_timeout, f" [{log_context}]" if log_context else "", holder_states, diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index 1519c21063ad..11d9d11ec73b 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -16,6 +16,7 @@ # under the License. import json # noqa: TID251 +import time from datetime import datetime, timedelta from typing import Any from unittest.mock import MagicMock, Mock, patch @@ -43,6 +44,7 @@ ) from superset.commands.report.execute import ( BaseReportState, + log_report_delivery_phase, persist_owned_report_execution_terminal_error, ReportNotTriggeredErrorState, ReportScheduleStateMachine, @@ -2732,6 +2734,88 @@ def test_terminal_persistence_retry_promotes_owned_working_execution( mock_db.session.commit.assert_called_once() +def test_terminal_persistence_retry_survives_database_failure( + mocker: MockerFixture, +) -> None: + """The last-resort retry must swallow its own DB failure: roll back, log, + and return False so the report's original exception is never masked.""" + execution_id = UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524") + mock_db = mocker.patch("superset.commands.report.execute.db") + mock_logger = mocker.patch("superset.commands.report.execute.logger") + mock_db.session.query.side_effect = Exception("database connection lost") + + assert not persist_owned_report_execution_terminal_error( + 11, + execution_id, + "boom", + "ReportScheduleWorkingTimeoutError", + ) + + # One pre-emptive rollback on entry, one in the exception handler. + assert mock_db.session.rollback.call_count == 2 + mock_db.session.commit.assert_not_called() + assert any( + "terminal_persistence_retry_failed" in call.args[0] + for call in mock_logger.exception.call_args_list + ) + + +def _exhausted_report_context(execution_id: UUID) -> ReportExecutionContext: + return ReportExecutionContext( + execution_id=execution_id, + report_schedule_id=11, + deadline=ReportExecutionDeadline( + total_seconds=0.01, + started_at=time.monotonic() - 10, + ), + ) + + +def test_delivery_phase_gate_noops_without_report_context( + mocker: MockerFixture, +) -> None: + mock_logger = mocker.patch("superset.commands.report.execute.logger") + + log_report_delivery_phase(None, None, "start", enforce_budget=True) + + mock_logger.info.assert_not_called() + + +def test_delivery_phase_gate_raises_when_budget_exhausted( + mocker: MockerFixture, +) -> None: + execution_id = UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524") + + with pytest.raises(ReportExecutionBudgetExceededError): + log_report_delivery_phase( + _exhausted_report_context(execution_id), + None, + "start", + enforce_budget=True, + ) + + +def test_delivery_phase_logging_without_enforcement_does_not_raise( + mocker: MockerFixture, +) -> None: + """enforce_budget=False is the post-send log call: it must record the + phase even when the budget is exhausted, not raise mid-notification.""" + execution_id = UUID("084e7ee6-5557-4ecd-9632-b7f39c9ec524") + mock_logger = mocker.patch("superset.commands.report.execute.logger") + + log_report_delivery_phase( + _exhausted_report_context(execution_id), + None, + "sent", + enforce_budget=False, + ) + + assert any( + call.args and call.args[0].startswith("report_delivery_") + for call in mock_logger.info.call_args_list + ) + + def test_terminal_persistence_retry_does_not_overwrite_newer_execution( mocker: MockerFixture, ) -> None: From c77359a7549f2ea42f8f9515d0176174e22e3c9f Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Tue, 4 Aug 2026 18:13:14 +0000 Subject: [PATCH 18/19] fix(reports): chart-capture readiness logs report container state, not vacuous holder counts A production alert on a chart produced a report_readiness_ready line with mounted_holders=0, reading as 'no charts': the holder counters query dashboard grid holders, which never exist on an explore page. Chart captures now log target=chart-container with the actual container state (missing/loading/terminal/mounted_pre_terminal) on both the ready and readiness-timeout lines; readiness itself was and remains decided by CHART_CONTAINER_READY_JS. Also makes the no-context fallback log context self-identifying (capture_kind= plus schedule/dashboard/chart ids) so alert capture lines are distinguishable from report captures and traceable without a ReportExecutionContext. Co-Authored-By: Claude --- superset/commands/report/execute.py | 11 ++- superset/utils/screenshot_utils.py | 15 ++++ superset/utils/webdriver.py | 51 ++++++++++++- .../commands/report/execute_test.py | 22 ++++++ tests/unit_tests/utils/webdriver_test.py | 72 +++++++++++++++++++ 5 files changed, 169 insertions(+), 2 deletions(-) diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 04d1bee5dc3e..a1fab5c8ebb8 100644 --- a/superset/commands/report/execute.py +++ b/superset/commands/report/execute.py @@ -285,7 +285,16 @@ def __init__( def _log_context(self) -> str: if self._report_execution_context: return self._report_execution_context.log_context - return f"execution_id={self._execution_id}" + # Alerts (and any capture without an execution context) get a + # self-identifying fallback so their log lines are distinguishable + # from report captures and traceable to the schedule. + return ( + f"capture_kind={str(self._report_schedule.type).lower()} " + f"execution_id={self._execution_id} " + f"report_schedule_id={self._report_schedule.id} " + f"dashboard_id={self._report_schedule.dashboard_id} " + f"chart_id={self._report_schedule.chart_id}" + ) def _budget_values(self) -> tuple[float | None, float | None]: if not self._report_execution_context: diff --git a/superset/utils/screenshot_utils.py b/superset/utils/screenshot_utils.py index a65c39f81194..6b87f7312202 100644 --- a/superset/utils/screenshot_utils.py +++ b/superset/utils/screenshot_utils.py @@ -241,6 +241,21 @@ class TiledScreenshotBudgetExceededError(ScreenshotTaskBudgetExceededError): }} """ +# Diagnostic companion to CHART_CONTAINER_READY_JS: reports why a chart +# capture is (or is not) ready. Chart pages have no dashboard grid holders, +# so the holder-count diagnostics read as vacuous zeros there. +CHART_CONTAINER_STATE_JS = f""" +() => {{ + const chart = document.querySelector('.chart-container'); + if (chart === null) {{ return 'missing'; }} + if (chart.querySelector('{LOADING_SELECTOR}') !== null) {{ return 'loading'; }} + if (chart.querySelector('{TERMINAL_MARKER_SELECTOR}') !== null) {{ + return 'terminal'; + }} + return 'mounted_pre_terminal'; +}} +""" + def combine_screenshot_tiles( screenshot_tiles: list[bytes], diff --git a/superset/utils/webdriver.py b/superset/utils/webdriver.py index 19bad3a0a549..d624a8dba2c0 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -47,6 +47,7 @@ from superset.utils.retries import retry_call from superset.utils.screenshot_utils import ( CHART_CONTAINER_READY_JS, + CHART_CONTAINER_STATE_JS, CHART_HOLDERS_READY_JS, FIND_CHART_HOLDER_STATES_JS, REPORT_CHART_HOLDERS_READY_JS, @@ -298,7 +299,7 @@ def _get_screenshot( return element.screenshot(**timeout_kwargs) @staticmethod - def _wait_for_charts_ready( + def _wait_for_charts_ready( # noqa: C901 page: Page, url: str, load_wait: int, @@ -455,6 +456,32 @@ def _wait_for_charts_ready( timeout=effective_load_wait * 1000, ) except PlaywrightTimeout: + if element_name == "chart-container": + # Chart captures have no dashboard grid holders; the holder + # counters below would read as vacuous zeros. Log the actual + # `.chart-container` state instead. + logger.warning( + "report_readiness_terminal url=%s target=chart-container " + "container_state=%s elapsed_seconds=%.2f " + "remaining_seconds=%s effective_wait_seconds=%.2f%s " + "terminal_reason=readiness_timeout; " + "aborting before capture or delivery", + url, + page.evaluate(CHART_CONTAINER_STATE_JS), + deadline.elapsed_seconds if deadline else elapsed, + ( + f"{deadline.remaining_seconds:.2f}" + if deadline + else ( + f"{remaining_budget:.2f}" + if remaining_budget is not None + else None + ) + ), + effective_load_wait, + context_suffix, + ) + raise chart_holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) unready_chart_holders = [ holder @@ -491,6 +518,28 @@ def _wait_for_charts_ready( chart_holder_states, ) raise + if element_name == "chart-container": + # Chart captures have no dashboard grid holders; the holder + # counters below would read as vacuous zeros. Log the actual + # `.chart-container` state instead. + logger.info( + "report_readiness_ready url=%s target=chart-container " + "container_state=%s elapsed_seconds=%.2f remaining_seconds=%s%s", + url, + page.evaluate(CHART_CONTAINER_STATE_JS), + deadline.elapsed_seconds if deadline else elapsed, + ( + f"{deadline.remaining_seconds:.2f}" + if deadline + else ( + f"{remaining_budget:.2f}" + if remaining_budget is not None + else None + ) + ), + context_suffix, + ) + return chart_holder_states = page.evaluate(FIND_CHART_HOLDER_STATES_JS) mounted_holders = len(chart_holder_states) ready_holders = sum( diff --git a/tests/unit_tests/commands/report/execute_test.py b/tests/unit_tests/commands/report/execute_test.py index 11d9d11ec73b..1094bb7776c1 100644 --- a/tests/unit_tests/commands/report/execute_test.py +++ b/tests/unit_tests/commands/report/execute_test.py @@ -2734,6 +2734,28 @@ def test_terminal_persistence_retry_promotes_owned_working_execution( mock_db.session.commit.assert_called_once() +def test_alert_log_context_fallback_is_self_identifying( + mocker: MockerFixture, +) -> None: + """Alerts run without a ReportExecutionContext by design; their fallback + log context must still identify the capture kind and schedule so alert + log lines are distinguishable from report captures.""" + execution_id = UUID("a92a71bd-91ed-41f4-a297-cb9c8da52450") + schedule = mocker.Mock(spec=ReportSchedule) + schedule.type = ReportScheduleType.ALERT + schedule.id = 11 + schedule.dashboard_id = None + schedule.chart_id = 19495 + + state = BaseReportState(schedule, datetime.utcnow(), execution_id) + + context = state._log_context + assert "capture_kind=alert" in context + assert f"execution_id={execution_id}" in context + assert "report_schedule_id=11" in context + assert "chart_id=19495" in context + + def test_terminal_persistence_retry_survives_database_failure( mocker: MockerFixture, ) -> None: diff --git a/tests/unit_tests/utils/webdriver_test.py b/tests/unit_tests/utils/webdriver_test.py index fc18687f2434..1a4cdf8d6de7 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -1697,6 +1697,78 @@ def test_report_readiness_budget_exhaustion_skips_poll_and_capture(self): page.wait_for_function.assert_not_called() page.screenshot.assert_not_called() + @patch("superset.utils.webdriver.logger") + def test_chart_capture_ready_logs_container_state_not_holder_counts( + self, mock_logger + ): + """Chart pages have no dashboard grid holders, so the ready line must + report the `.chart-container` state instead of vacuous zero counters + (which read as "no charts" in customer logs).""" + from superset.utils.screenshot_utils import CHART_CONTAINER_STATE_JS + + page = MagicMock() + page.wait_for_function.return_value = None + page.evaluate.side_effect = lambda script: ( + "terminal" if script == CHART_CONTAINER_STATE_JS else [] + ) + + with patch( + "superset.utils.webdriver.resolve_screenshot_task_budget_seconds", + return_value=None, + ): + WebDriverPlaywright._wait_for_charts_ready( + page, + "http://example.com", + 10, + "chart-container", + log_context="capture_kind=alert execution_id=abc-123", + ) + + ready_call = next( + call + for call in mock_logger.info.call_args_list + if call.args and call.args[0].startswith("report_readiness_ready") + ) + assert "target=chart-container" in ready_call.args[0] + assert "mounted_holders" not in ready_call.args[0] + assert "terminal" in ready_call.args + assert " [capture_kind=alert execution_id=abc-123]" in ready_call.args + + @patch("superset.utils.webdriver.logger") + def test_chart_capture_timeout_logs_container_state(self, mock_logger): + from superset.utils.screenshot_utils import CHART_CONTAINER_STATE_JS + from superset.utils.webdriver import PlaywrightTimeout + + page = MagicMock() + page.wait_for_function.side_effect = PlaywrightTimeout() + page.evaluate.side_effect = lambda script: ( + "loading" if script == CHART_CONTAINER_STATE_JS else [] + ) + + with ( + patch( + "superset.utils.webdriver.resolve_screenshot_task_budget_seconds", + return_value=None, + ), + pytest.raises(PlaywrightTimeout), + ): + WebDriverPlaywright._wait_for_charts_ready( + page, + "http://example.com", + 10, + "chart-container", + ) + + terminal_call = next( + call + for call in mock_logger.warning.call_args_list + if call.args and call.args[0].startswith("report_readiness_terminal") + ) + assert "target=chart-container" in terminal_call.args[0] + assert "terminal_reason=readiness_timeout" in terminal_call.args[0] + assert "mounted_holders" not in terminal_call.args[0] + assert "loading" in terminal_call.args + def test_zero_load_wait_without_task_budget_preserves_playwright_no_timeout(self): page = MagicMock() page.evaluate.return_value = [] From af5bcc25744cbac3904963b0f8ac0643d2d254dc Mon Sep 17 00:00:00 2001 From: Elizabeth Thompson Date: Wed, 5 Aug 2026 20:20:10 +0000 Subject: [PATCH 19/19] chore: retrigger CI MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cypress-matrix failed on a GitHub Actions platform hiccup ('Our services aren't available right now' in the job log) that corrupted the step env resolution for that run — PARALLELISM/PARALLEL_ID were dropped from the step env, so the unquoted expansion in bashlib.sh collapsed into '--parallelism --parallelism-id' and argparse failed. Reruns replay the same corrupted run object; a fresh synchronize event gets a clean context. No file changes.