diff --git a/UPDATING.md b/UPDATING.md index 7c46ccecbd7..22ab5ae3aee 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 adff1abb573..e2262bcc584 100644 --- a/docs/admin_docs/configuration/alerts-reports.mdx +++ b/docs/admin_docs/configuration/alerts-reports.mdx @@ -245,6 +245,53 @@ class CeleryConfig: } CELERY_CONFIG = CeleryConfig +# 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 +# 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 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 +# 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. +# +# 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 +# shared execution deadline above. SCREENSHOT_LOCATE_WAIT = 100 SCREENSHOT_LOAD_WAIT = 600 diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py index 840c4c00046..7efe14820e9 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 @@ -27,6 +28,7 @@ from uuid import UUID 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 @@ -89,6 +91,12 @@ from superset.utils.csv import get_chart_csv_data, get_chart_dataframe 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 ( + 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 from superset.utils.urls import get_url_path @@ -123,6 +131,137 @@ def resolve_executor_user(model: ReportSchedule) -> tuple["User", str]: return user, username +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, + ) + 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, + ) + + +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 @@ -133,13 +272,51 @@ class BaseReportState: 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 + # 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: + 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 +328,17 @@ class BaseReportState: """ 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: """ @@ -224,7 +412,13 @@ class BaseReportState: 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 @@ -237,13 +431,16 @@ class BaseReportState: 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( @@ -252,7 +449,7 @@ class BaseReportState: 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: @@ -266,7 +463,7 @@ class BaseReportState: 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: @@ -592,7 +789,9 @@ class BaseReportState: 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,28 +802,55 @@ class BaseReportState: 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 + ), ) + 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: elapsed_seconds = ( 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 +865,20 @@ class BaseReportState: :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 +1028,17 @@ class BaseReportState: 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 +1047,17 @@ class BaseReportState: 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 @@ -821,7 +1080,11 @@ class BaseReportState: elapsed_seconds, self._execution_id, ) + if self._report_schedule.type == ReportScheduleType.REPORT: + raise raise timeout_error() from ex + except ReportExecutionBudgetExceededError: + raise except Exception as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time @@ -855,7 +1118,15 @@ class BaseReportState: 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 @@ -876,7 +1147,11 @@ class BaseReportState: elapsed_seconds, self._execution_id, ) + if self._report_schedule.type == ReportScheduleType.REPORT: + raise raise ReportScheduleDataFrameTimeout() from ex + except ReportExecutionBudgetExceededError: + raise except Exception as ex: elapsed_seconds = ( datetime.now(timezone.utc).replace(tzinfo=None) - start_time @@ -1048,10 +1323,17 @@ class BaseReportState: :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: + log_report_delivery_phase( + report_context, + getattr(recipient, "type", None), + "start", + enforce_budget=True, + ) if app.config["ALERT_REPORTS_NOTIFICATION_DRY_RUN"]: logger.info( "Would send notification for alert %s, to %s. " @@ -1062,6 +1344,12 @@ class BaseReportState: ) else: notification.send() + 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 logger.info( @@ -1070,6 +1358,12 @@ class BaseReportState: self.update_report_schedule_slack_v2() recipient.type = ReportRecipientType.SLACKV2 notification = create_notification(recipient, notification_content) + log_report_delivery_phase( + report_context, + recipient.type, + "retry", + enforce_budget=True, + ) notification.send() except ( UpdateFailedError, @@ -1359,11 +1653,22 @@ class BaseReportState: ) if not last_working: return False + working_timeout = self._report_schedule.working_timeout + if self._report_schedule.type == ReportScheduleType.REPORT: + # 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 ( - 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 ) @@ -1430,6 +1735,21 @@ class ReportNotTriggeredErrorState(BaseReportState): 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 + # 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): @@ -1442,9 +1762,10 @@ class ReportNotTriggeredErrorState(BaseReportState): 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", @@ -1520,6 +1841,12 @@ class ReportWorkingState(BaseReportState): self._execution_id, ) exception_timeout = ReportScheduleWorkingTimeoutError() + # 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), @@ -1530,9 +1857,23 @@ class ReportWorkingState(BaseReportState): 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 @@ -1621,9 +1962,10 @@ class ReportSuccessState(BaseReportState): 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", @@ -1657,10 +1999,12 @@ class ReportScheduleStateMachine: # pylint: disable=too-few-public-methods 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: @@ -1672,6 +2016,7 @@ class ReportScheduleStateMachine: # pylint: disable=too-few-public-methods self._report_schedule, self._scheduled_dttm, self._execution_id, + self._report_execution_context, ).next() break else: @@ -1692,11 +2037,62 @@ class AsyncExecuteReportScheduleCommand(BaseCommand): self._execution_id = UUID(task_id) 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 = resolve_report_execution_budget_seconds( + app.config, + working_timeout=self._model.working_timeout, + ) + 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 @@ -1727,10 +2123,16 @@ class AsyncExecuteReportScheduleCommand(BaseCommand): # 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 = ( @@ -1742,9 +2144,33 @@ class AsyncExecuteReportScheduleCommand(BaseCommand): elapsed_seconds, self._execution_id, ) - except CommandException: + except (CommandException, SoftTimeLimitExceeded) as ex: + 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, + 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 + and owns_report_working_state + ): + 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/superset/commands/report/execute_now.py b/superset/commands/report/execute_now.py index ee61ae74ee6..cea73f4770f 100644 --- a/superset/commands/report/execute_now.py +++ b/superset/commands/report/execute_now.py @@ -33,7 +33,8 @@ from superset.commands.report.exceptions import ( ) 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 @@ class ExecuteReportScheduleNowCommand(BaseCommand): "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 9eac73fcb3d..fa8af7294a8 100644 --- a/superset/config.py +++ b/superset/config.py @@ -2452,6 +2452,37 @@ ALERT_REPORTS_WORKING_TIME_OUT_LAG = int(timedelta(seconds=10).total_seconds()) 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. 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; +# 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 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() +) ALERT_REPORTS_DEFAULT_RETENTION = 90 ALERT_REPORTS_DEFAULT_CRON_VALUE = "0 0 * * *" # every day # Retry backoff: first retry waits base seconds, each subsequent retry doubles. diff --git a/superset/initialization/__init__.py b/superset/initialization/__init__.py index a09011c7df8..09e852c1b91 100644 --- a/superset/initialization/__init__.py +++ b/superset/initialization/__init__.py @@ -75,6 +75,7 @@ from superset.superset_typing import FlaskResponse 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 @@ class SupersetAppInitializer: # pylint: disable=too-many-public-methods """ 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/mcp_service/screenshot/pooled_screenshot.py b/superset/mcp_service/screenshot/pooled_screenshot.py index 977d4899b9f..136806b4293 100644 --- a/superset/mcp_service/screenshot/pooled_screenshot.py +++ b/superset/mcp_service/screenshot/pooled_screenshot.py @@ -33,6 +33,7 @@ from selenium.webdriver.support.ui import WebDriverWait 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 @@ class PooledBaseScreenshot(BaseScreenshot): 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 @@ class PooledBaseScreenshot(BaseScreenshot): 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 5bf1a8d82b2..2a65ba1de9c 100644 --- a/superset/tasks/scheduler.py +++ b/superset/tasks/scheduler.py @@ -39,6 +39,7 @@ from superset.daos.report import ReportScheduleDAO 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 +49,7 @@ from superset.tasks.manager import TaskManager 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__) @@ -98,19 +100,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) @@ -150,6 +147,17 @@ def execute( report_schedule_id, 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", + task_id, + report_schedule_id, + exc_info=True, + ) + self.update_state(state="FAILURE") + raise except ReportScheduleUnexpectedError: logger.exception( "An unexpected error occurred while executing the report: %s", task_id diff --git a/superset/utils/report_execution.py b/superset/utils/report_execution.py new file mode 100644 index 00000000000..690dfcaa454 --- /dev/null +++ b/superset/utils/report_execution.py @@ -0,0 +1,269 @@ +# 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 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.""" + + 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") + + +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"]) + ) + 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); " + "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.""" + + 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, + ) + + 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.""" + + 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 + + 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.""" + + 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 is_report: + validate_report_execution_config(config) + if not config["ALERT_REPORTS_WORKING_TIME_OUT_KILL"]: + return {} + if is_report: + 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, + "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 82a06fd66c0..6b87f731220 100644 --- a/superset/utils/screenshot_utils.py +++ b/superset/utils/screenshot_utils.py @@ -25,6 +25,11 @@ from typing import TYPE_CHECKING 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) @@ -214,6 +219,13 @@ FIND_CHART_HOLDER_STATES_JS = f""" 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; }" +) +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; }}" ) @@ -229,8 +241,27 @@ CHART_CONTAINER_READY_JS = f""" }} """ +# 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]) -> bytes: + +def combine_screenshot_tiles( + screenshot_tiles: list[bytes], + *, + allow_partial_fallback: bool = True, +) -> bytes: """ Combine multiple screenshot tiles into a single vertical image. @@ -270,8 +301,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 @@ -281,6 +315,9 @@ def take_tiled_screenshot( # noqa: C901 load_wait: int = 60, animation_wait: int = 0, 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. @@ -294,6 +331,15 @@ def take_tiled_screenshot( # noqa: C901 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. + 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 @@ -304,6 +350,8 @@ def take_tiled_screenshot( # noqa: C901 verifiably captured. Callers must treat this as a hard failure rather than fall back to an unchecked/partial screenshot. """ + 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 @@ -315,19 +363,99 @@ 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 - # Cap the whole tiled operation against the running Celery task's own - # time limit, using the same runtime derivation as the non-tiled - # readiness wait (#42253/#42427). Unlike that path, a None budget does - # not mean "keep the configured timeout": per-tile waits accumulate, so - # the operation falls back to a fixed total ceiling instead. - wait_budget_seconds = resolve_screenshot_task_budget_seconds(log_context) - if wait_budget_seconds is None: - wait_budget_seconds = float(TILED_SCREENSHOT_TOTAL_WAIT_BUDGET_SECONDS) - start_time = time.monotonic() + if screenshot_started_at is None: + screenshot_started_at = time.monotonic() + task_budget = ( + None + if report_execution_context + else resolve_screenshot_task_budget_seconds(log_context) + ) + # Non-report callers (thumbnails) have no execution deadline; cap the + # whole tiled operation against the running Celery task's own limit, + # falling back to a fixed total ceiling when no usable limit exists -- + # per-tile waits accumulate, so "no budget" must not mean "uncapped" + # (#42118; see TILED_SCREENSHOT_TOTAL_WAIT_BUDGET_SECONDS). + if report_execution_context is None and task_budget is None: + task_budget = float(TILED_SCREENSHOT_TOTAL_WAIT_BUDGET_SECONDS) + + 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 + ) + + if report_execution_context: + mount_wait = _timeout_seconds( + "chart_holder_mount", + reserve_seconds=report_execution_context.readiness_reserve_seconds, + ) + 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"""() => {{ @@ -360,8 +488,9 @@ def take_tiled_screenshot( # noqa: C901 screenshot_tiles: list[bytes] = [] - def _raise_if_budget_exhausted(elapsed: float, remaining_budget: float) -> None: - if remaining_budget > 0: + def _raise_if_budget_exhausted() -> None: + elapsed, remaining = _deadline_values() + if remaining is None or remaining > 0: return # A customer-side chart-loading issue (a slow/hung dashboard), # not a Superset system fault, so this is a WARNING rather @@ -369,20 +498,17 @@ def take_tiled_screenshot( # noqa: C901 # deliberately downgraded screenshot timeout logs the same way. logger.warning( "Tiled screenshot time budget exhausted on tile %s/%s: " - "%s/%s tiles captured so far, %.1fs elapsed of a %.1fs " - "budget. Aborting instead of capturing remaining tiles " - "unchecked.%s", + "%s/%s tiles captured so far, %.1fs elapsed. Aborting " + "instead of capturing remaining tiles unchecked.%s", i + 1, num_tiles, len(screenshot_tiles), num_tiles, elapsed, - wait_budget_seconds, context_suffix, ) raise TiledScreenshotBudgetExceededError( - f"Tiled screenshot budget of " - f"{wait_budget_seconds:.1f}s exhausted " + f"Tiled screenshot budget exhausted " f"after {len(screenshot_tiles)}/{num_tiles} tiles" ) @@ -392,9 +518,7 @@ def take_tiled_screenshot( # noqa: C901 # later) tile is actually ready to capture -- fail loudly instead # of silently snapshotting a spinner or blank chart, or running # past the Celery task time limit and getting SIGKILLed. - elapsed = time.monotonic() - start_time - remaining_budget = wait_budget_seconds - elapsed - _raise_if_budget_exhausted(elapsed, remaining_budget) + _raise_if_budget_exhausted() # Calculate scroll position to show this tile's content scroll_y = dashboard_top + (i * tile_height) @@ -406,16 +530,12 @@ def take_tiled_screenshot( # noqa: C901 # Wait for scroll to settle and content to load page.wait_for_timeout(SCROLL_SETTLE_TIMEOUT_MS) - # Recompute the remaining budget after the scroll-settle sleep -- - # which itself consumes real wall-clock time -- rather than - # reusing the value from before it, so the readiness-check - # timeout below is capped against a fresh number instead of a - # stale one that would let each tile overrun the budget by up - # to one settle interval. - tile_wait_start = time.monotonic() - elapsed = tile_wait_start - start_time - remaining_budget = wait_budget_seconds - elapsed - _raise_if_budget_exhausted(elapsed, remaining_budget) + # Re-check after the scroll-settle sleep -- which itself consumes + # real wall-clock time -- so the readiness-check timeout below is + # derived from a fresh remaining value instead of a stale one + # that would let each tile overrun the budget by up to one settle + # interval (_timeout_seconds also recomputes at call time). + _raise_if_budget_exhausted() # Wait for every chart holder visible in the current viewport to reach # a terminal state (rendered chart or error/empty state), capped at @@ -425,50 +545,78 @@ def take_tiled_screenshot( # noqa: C901 # placeholders rendered for off-screen charts. A holder that hasn't # mounted anything yet does not satisfy this check -- unlike checking # for the absence of `.loading`, which passes vacuously in that case. - tile_load_wait = min(load_wait, remaining_budget) + 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, + ( + REPORT_CHART_HOLDERS_READY_JS + if report_execution_context + else CHART_HOLDERS_READY_JS + ), 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 (waited %.1fs of a %ss requested " - "load_wait; %.1fs elapsed of a %.1fs total budget; %s/%s " - "tiles captured so far)%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 " + "tiles_captured=%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, - tile_load_wait, - load_wait, - time.monotonic() - start_time, - wait_budget_seconds, len(screenshot_tiles), num_tiles, + 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, ) readiness_wait_elapsed = time.monotonic() - tile_wait_start @@ -481,9 +629,30 @@ def take_tiled_screenshot( # noqa: C901 # (rather than raise) once the budget runs out. animation_wait_elapsed = 0.0 if animation_wait > 0: - elapsed = time.monotonic() - start_time - remaining_budget = wait_budget_seconds - elapsed - tile_animation_wait = max(0, min(animation_wait, remaining_budget)) + # Cosmetic settling, not a readiness check: cap at whatever + # remains and simply skip (rather than raise) once the + # deadline/budget runs out. + if report_execution_context: + try: + tile_animation_wait = min( + float(animation_wait), + _timeout_seconds( + "chart_animation", + reserve_seconds=( + report_execution_context.readiness_reserve_seconds + ), + ), + ) + except ReportExecutionBudgetExceededError: + tile_animation_wait = 0.0 + else: + try: + tile_animation_wait = _timeout_seconds( + "chart_animation", + requested_seconds=float(animation_wait), + ) + except TiledScreenshotBudgetExceededError: + tile_animation_wait = 0.0 if tile_animation_wait > 0: animation_wait_start = time.monotonic() page.wait_for_timeout(tile_animation_wait * 1000) @@ -538,22 +707,83 @@ def take_tiled_screenshot( # noqa: C901 } # 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 + 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() + 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) + combined_screenshot = combine_screenshot_tiles( + screenshot_tiles, + allow_partial_fallback=report_execution_context is None, + ) return combined_screenshot - except TiledScreenshotBudgetExceededError: - # Budget exhaustion must fail cleanly, not be swallowed into the - # generic `return None` degradation below -- the raise carries the - # budget diagnostics to the caller, which fails the capture loudly - # (#42273) instead of receiving an anonymous empty result. + except (ReportExecutionBudgetExceededError, TiledScreenshotBudgetExceededError): + # Budget/deadline exhaustion must fail cleanly, not be swallowed into + # the generic `return None` degradation below -- the raise carries the + # diagnostics to the caller, which fails the capture loudly (#42273) + # instead of receiving an anonymous empty result. + 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: diff --git a/superset/utils/screenshots.py b/superset/utils/screenshots.py index 32b7f2bda23..168816135ca 100644 --- a/superset/utils/screenshots.py +++ b/superset/utils/screenshots.py @@ -33,6 +33,7 @@ from superset.exceptions import ( ) 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, @@ -241,11 +242,16 @@ class BaseScreenshot: 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 4b8c1837275..d624a8dba2c 100644 --- a/superset/utils/webdriver.py +++ b/superset/utils/webdriver.py @@ -41,11 +41,16 @@ from selenium.webdriver.support import expected_conditions as EC # noqa: N812 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, + CHART_CONTAINER_STATE_JS, CHART_HOLDERS_READY_JS, FIND_CHART_HOLDER_STATES_JS, + REPORT_CHART_HOLDERS_READY_JS, resolve_screenshot_task_budget_seconds, ScreenshotTaskBudgetExceededError, take_tiled_screenshot, @@ -217,6 +222,7 @@ class WebDriverProxy(ABC): 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 @@ -278,20 +284,29 @@ class WebDriverPlaywright(WebDriverProxy): 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( + def _wait_for_charts_ready( # noqa: C901 page: Page, url: str, load_wait: int, 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 @@ -313,6 +328,10 @@ class WebDriverPlaywright(WebDriverProxy): 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) @@ -321,16 +340,47 @@ class WebDriverPlaywright(WebDriverProxy): 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( @@ -339,36 +389,47 @@ class WebDriverPlaywright(WebDriverProxy): 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, ) - raise ScreenshotTaskBudgetExceededError( - f"Screenshot task budget of {task_budget:.2f}s exhausted " - "before chart readiness" + 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 ) + 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, " @@ -380,40 +441,125 @@ class WebDriverPlaywright(WebDriverProxy): 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, 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 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) + 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( + 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, @@ -421,8 +567,15 @@ class WebDriverPlaywright(WebDriverProxy): 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. " @@ -452,9 +605,24 @@ class WebDriverPlaywright(WebDriverProxy): 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( @@ -464,6 +632,16 @@ class WebDriverPlaywright(WebDriverProxy): ) 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 @@ -474,7 +652,23 @@ class WebDriverPlaywright(WebDriverProxy): "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 @@ -490,7 +684,23 @@ class WebDriverPlaywright(WebDriverProxy): # numbers below describe the snapshot, not the final DOM. slice_container_elems = slice_container_locator.all() for slice_container_elem in slice_container_elems: - 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 {} + ) + ) rendered_chart_count += 1 except PlaywrightTimeout: # Customer-side chart loading is often just slow, not a @@ -522,9 +732,18 @@ class WebDriverPlaywright(WebDriverProxy): 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}\"); @@ -576,10 +795,15 @@ class WebDriverPlaywright(WebDriverProxy): 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( @@ -592,6 +816,9 @@ class WebDriverPlaywright(WebDriverProxy): load_wait=self._screenshot_load_wait, animation_wait=selenium_animation_wait, 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 @@ -599,11 +826,16 @@ class WebDriverPlaywright(WebDriverProxy): # silently delivering a screenshot of spinners or # a blank dashboard. Fail the capture loudly # (report error, thumbnail cache ERROR) instead of - # guessing at a "safer" fallback. + # guessing at a "safer" fallback (#42273) -- for + # thumbnails too, since the caller treats the + # raise as a clean cache-ERROR, never caching or + # serving a blank. logger.warning( - "Tiled screenshot failed for url %s and no " - "safe fallback exists; failing the capture", + "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}" @@ -632,8 +864,19 @@ class WebDriverPlaywright(WebDriverProxy): 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 +887,21 @@ class WebDriverPlaywright(WebDriverProxy): 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", @@ -668,8 +924,19 @@ class WebDriverPlaywright(WebDriverProxy): 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, @@ -680,8 +947,21 @@ class WebDriverPlaywright(WebDriverProxy): 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", @@ -958,7 +1238,24 @@ class WebDriverSelenium(WebDriverProxy): 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: @@ -966,9 +1263,26 @@ class WebDriverSelenium(WebDriverProxy): 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) @@ -982,57 +1296,193 @@ class WebDriverSelenium(WebDriverProxy): 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 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, + report_execution_context.readiness_reserve_seconds, ) - except TimeoutException: - logger.info("Timeout Exception caught") - # Fallback to allow a screenshot of an empty dashboard try: - WebDriverWait(driver, 0).until( - EC.visibility_of_all_elements_located( - (By.CLASS_NAME, "grid-container") + WebDriverWait(driver, readiness_timeout).until( + lambda webdriver: webdriver.execute_script( + f"return ({readiness_predicate})()" ) ) - except Exception: + 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 + 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, + len(holder_states), + sum( + holder.get("state") in ready_states + for holder in holder_states + ), + f"{deadline.elapsed_seconds:.2f}", + f"{deadline.remaining_seconds:.2f}", + f" [{log_context}]" if log_context else "", + ) + except TimeoutException: + 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 logger.warning( - "Selenium timed out waiting for dashboard to draw at url %s", + "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, + len(holder_states), + ready_holders, + f"{deadline.elapsed_seconds:.2f}", + f"{deadline.remaining_seconds:.2f}", + 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, "chart-container") + ) + ) + except TimeoutException: + 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 + 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 - 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 - 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( @@ -1051,6 +1501,12 @@ class WebDriverSelenium(WebDriverProxy): 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/commands_tests.py b/tests/integration_tests/reports/commands_tests.py index 0b04854f1e4..533f8eacb6c 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 @@ from slack_sdk.errors import ( SlackRequestError, SlackTokenRotationError, ) +from sqlalchemy.exc import OperationalError from sqlalchemy.sql import func, text try: @@ -52,12 +54,12 @@ from superset.commands.report.exceptions import ( AlertQueryMultipleRowsError, ReportScheduleClientErrorsException, ReportScheduleCsvFailedError, - ReportScheduleCsvTimeout, ReportScheduleNotFoundError, ReportSchedulePreviousWorkingError, ReportScheduleScreenshotFailedError, ReportScheduleScreenshotTimeout, ReportScheduleSystemErrorsException, + ReportScheduleUnexpectedError, ReportScheduleWorkingTimeoutError, ) from superset.commands.report.execute import ( @@ -86,6 +88,8 @@ from superset.reports.notifications.exceptions import ( 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 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 @@ -162,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 @@ -188,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: @@ -877,7 +908,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 @@ -1926,9 +1959,93 @@ 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 +@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_refused_execution_history(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_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, + error_message: Optional[str] = None, + *, + log_state: ReportState | None = None, + reuse_working_log: bool = True, + ) -> None: + raise OperationalError( + "INSERT report_execution_log", + {}, + RuntimeError("connection lost while refusing replay"), + ) + + monkeypatch.setattr( + BaseReportState, + "create_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): """ @@ -1951,6 +2068,8 @@ def test_report_schedule_working_timeout(create_report_slack_chart_working): assert ReportScheduleWorkingTimeoutError.message in [ log.error_message for log in logs ] + 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 @@ -2324,19 +2443,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( @@ -2405,6 +2523,99 @@ 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 timed_out_log.start_dttm is not None + assert timed_out_log.end_dttm is not None + # 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( + "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/integration_tests/reports/scheduler_tests.py b/tests/integration_tests/reports/scheduler_tests.py index 9bb2528f6f7..d7a62587137 100644 --- a/tests/integration_tests/reports/scheduler_tests.py +++ b/tests/integration_tests/reports/scheduler_tests.py @@ -23,7 +23,7 @@ from freezegun import freeze_time 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 @@ -108,6 +108,40 @@ 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, + ) + + # 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. 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() + 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): @@ -178,6 +212,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 5b0337a1a99..65f5d23ecf1 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 @@ -40,10 +41,11 @@ from superset.commands.report.exceptions import ( ReportScheduleUnexpectedError, ReportScheduleWorkingTimeoutError, ReportScheduleXlsxFailedError, - ReportScheduleXlsxTimeout, ) from superset.commands.report.execute import ( BaseReportState, + log_report_delivery_phase, + persist_owned_report_execution_terminal_error, ReportNotTriggeredErrorState, ReportScheduleStateMachine, ReportSuccessState, @@ -63,6 +65,11 @@ from superset.reports.models import ( ) 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 @@ -1428,11 +1435,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, @@ -1665,14 +1667,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}) @@ -1692,10 +1690,48 @@ 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) +@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)`` @@ -2257,6 +2293,7 @@ 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, @@ -2278,17 +2315,167 @@ 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, ) +def test_working_timeout_replay_delegates_single_terminal_update( + 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.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, + ) + update = mocker.patch.object(state, "update_report_schedule_and_log") + + with pytest.raises(ReportScheduleWorkingTimeoutError): + state.next() + + update.assert_called_once_with( + ReportState.ERROR, + error_message=str(ReportScheduleWorkingTimeoutError()), + ) + assert working_log.state == ReportState.WORKING + + +def test_stale_recovery_delegates_terminal_update_without_delivery( + mocker: MockerFixture, +) -> None: + """Recovery unblocks the schedule without racing the old worker's audit row.""" + 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.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", + return_value=working_log, + ) + recovered_next = mocker.patch.object(ReportNotTriggeredErrorState, "next") + update = mocker.patch.object(state, "update_report_schedule_and_log") + + with pytest.raises(ReportScheduleWorkingTimeoutError): + state.next() + + update.assert_called_once_with( + ReportState.ERROR, + error_message=str(ReportScheduleWorkingTimeoutError()), + ) + assert working_log.state == ReportState.WORKING + assert working_log.error_message is None + recovered_next.assert_not_called() + + +def test_report_working_state_recovery_is_bounded_by_execution_budget( + app: SupersetApp, + mocker: MockerFixture, +) -> None: + """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, + 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, + ) + + 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( + 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_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: @@ -2491,6 +2678,204 @@ def test_create_log_success_commits(mocker: MockerFixture) -> None: mock_db.session.rollback.assert_not_called() +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.ERROR + schedule.last_value = None + schedule.last_value_row_json = None + working_log = mocker.Mock() + + mock_db = mocker.patch("superset.commands.report.execute.db") + 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, + ) + + state.create_log(error_message="working timeout") + + 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_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_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: + """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: + 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: @@ -2514,6 +2899,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 e69ed0734fd..dd1a0caa12e 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 @@ from superset.commands.report.exceptions import ( 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,40 @@ 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_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() + + _, 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/initialization_test.py b/tests/unit_tests/initialization_test.py index 445afc733c0..c34d2f157c9 100644 --- a/tests/unit_tests/initialization_test.py +++ b/tests/unit_tests/initialization_test.py @@ -121,6 +121,25 @@ class TestSupersetApp: 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/tasks/test_scheduler_soft_timeout.py b/tests/unit_tests/tasks/test_scheduler_soft_timeout.py new file mode 100644 index 00000000000..6eb0a80e776 --- /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 + ) 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 00000000000..6c99d53482d --- /dev/null +++ b/tests/unit_tests/utils/test_report_execution.py @@ -0,0 +1,209 @@ +# 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, + MIN_REPORT_EXECUTION_WORK_SECONDS, + ReportExecutionBudgetExceededError, + ReportExecutionContext, + ReportExecutionDeadline, + resolve_report_execution_budget_seconds, + 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( + 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_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 = _report_config() + + 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} + + +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"), + [ + ({"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/test_screenshot_utils.py b/tests/unit_tests/utils/test_screenshot_utils.py index f5569e8a741..1e5c602cc8a 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, @@ -33,6 +38,25 @@ from superset.utils.screenshot_utils import ( ) +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() @@ -155,6 +179,16 @@ class TestCombineScreenshotTiles: # 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 @@ -197,6 +231,71 @@ class TestTakeTiledScreenshot: # 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, + report_execution_context=_report_context(), + ) + + 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, + report_execution_context=_report_context(), + ) + + 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() @@ -365,8 +464,8 @@ class TestTakeTiledScreenshot: # 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,14 +496,21 @@ class TestTakeTiledScreenshot: """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(), ) - # 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 @@ -421,27 +527,31 @@ class TestTakeTiledScreenshot: 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: 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 # 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). @@ -450,23 +560,20 @@ class TestTakeTiledScreenshot: 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 # tile_load_wait (uncapped: budget remains) - assert warning_args[6] == 30 # requested load_wait - assert isinstance(warning_args[7], float) # total elapsed vs budget - assert warning_args[8] == 1440 # total budget (fixed fallback) - assert warning_args[9] == 0 # tiles captured so far - assert warning_args[10] == 3 # total tiles - assert warning_args[11] == "" # 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 warning_args[7] == 0 # tiles captured so far + assert warning_args[8] == 3 # total tiles + assert isinstance(warning_args[9], float) # tile elapsed + assert isinstance(warning_args[10], float) # total elapsed + assert warning_args[12] == 30 # effective wait + assert "capture_kind=report" in warning_args[13] # 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[12] == [{"chartId": "42", "state": "waiting_on_database"}] + assert warning_args[14] == [{"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 @@ -478,6 +585,7 @@ class TestTakeTiledScreenshot: {"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: @@ -492,7 +600,7 @@ class TestTakeTiledScreenshot: ) warning_args = mock_logger.warning.call_args[0] - assert warning_args[11] == " [execution_id=abc-123]" + assert warning_args[13] == " [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). @@ -510,6 +618,8 @@ class TestTakeTiledScreenshot: # 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 @@ -517,6 +627,7 @@ class TestTakeTiledScreenshot: {"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"): @@ -540,6 +651,7 @@ class TestTakeTiledScreenshot: 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): @@ -551,6 +663,8 @@ class TestTakeTiledScreenshot: '.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" 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 @@ -567,6 +681,7 @@ class TestTakeTiledScreenshot: CHART_HOLDERS_READY_JS, FIND_CHART_HOLDER_STATES_JS, FIND_UNREADY_CHART_HOLDERS_JS, + REPORT_CHART_HOLDERS_READY_JS, ) for js in ( @@ -574,6 +689,7 @@ class TestTakeTiledScreenshot: 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 @@ -620,6 +736,29 @@ class TestTakeTiledScreenshot: 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 @@ -793,8 +932,10 @@ class TestTileWaitBudget: mock_page, "dashboard", tile_height=2000, load_wait=100 ) - # Only the first tile was captured before the budget ran out. - assert mock_page.screenshot.call_count == 1 + # Nothing is captured: the pre-capture bounded check raises before + # snapshotting the tile whose readiness wait consumed the budget + # (the capture call itself is deadline-bounded in this design). + assert mock_page.screenshot.call_count == 0 # Tiles were never combined -- the function raised before that point. mock_combine.assert_not_called() @@ -804,16 +945,7 @@ class TestTileWaitBudget: assert mock_logger.error.call_count == 0 mock_logger.warning.assert_called_once() warning_args = mock_logger.warning.call_args[0] - assert "budget exhausted" in warning_args[0] - # tile index, tiles total, tiles captured, tiles total, - # elapsed seconds, budget seconds, log-context suffix - assert warning_args[1] == 2 - assert warning_args[2] == 3 - assert warning_args[3] == 1 - assert warning_args[4] == 3 - assert warning_args[5] == 1000 - assert warning_args[6] == 1000 - assert warning_args[7] == "" + assert "terminal_reason=budget_exhausted" in warning_args[0] def test_budget_exhausted_warning_includes_log_context( self, mock_page, monkeypatch @@ -896,6 +1028,60 @@ class TestTileWaitBudget: 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 8b0ab64c364..1a4cdf8d6de 100644 --- a/tests/unit_tests/utils/webdriver_test.py +++ b/tests/unit_tests/utils/webdriver_test.py @@ -15,10 +15,15 @@ # specific language governing permissions and limitations # under the License. -from unittest.mock import MagicMock, patch, PropertyMock +from unittest.mock import ANY, call, 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 @@ from superset.utils.webdriver import ( ) +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,121 @@ class TestWebDriverSelenium: 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 + + @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.""" @@ -770,16 +915,12 @@ class TestWebDriverPlaywrightErrorHandling: 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") @@ -1165,15 +1306,19 @@ class TestWebDriverPlaywrightErrorHandling: with pytest.raises( PlaywrightTimeout, match="Tiled screenshot failed for url" ): - 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_element.screenshot.assert_not_called() - mock_logger.warning.assert_any_call( - "Tiled screenshot failed for url %s and no safe fallback " - "exists; failing the capture", - "http://example.com", + assert any( + "no safe fallback exists" in call.args[0] + for call in mock_logger.warning.call_args_list ) @@ -1279,8 +1424,11 @@ class TestWebDriverPlaywrightChartReadiness: 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") @@ -1299,7 +1447,14 @@ class TestWebDriverPlaywrightChartReadiness: 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] @@ -1315,22 +1470,56 @@ class TestWebDriverPlaywrightChartReadiness: @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): + with pytest.raises(PlaywrightTimeout): + WebDriverPlaywright("chrome").get_screenshot( + "http://example.com", + "standalone", + MagicMock(), + report_execution_context=_report_context(), + ) + + 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") + @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): - WebDriverPlaywright("chrome").get_screenshot( - "http://example.com", "standalone", MagicMock() + result = 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" - ) + 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") @@ -1398,9 +1587,7 @@ class TestWebDriverPlaywrightChartReadiness: 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") @@ -1435,6 +1622,153 @@ class TestWebDriverPlaywrightChartReadiness: 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() + + @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 = [] @@ -1515,12 +1849,6 @@ class TestWebDriverPlaywrightChartReadiness: 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", @@ -1528,8 +1856,8 @@ class TestWebDriverPlaywrightChartReadiness: 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() @@ -1621,7 +1949,7 @@ class TestWebDriverPlaywrightAnimationWaitOrder: 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] = [] @@ -1644,6 +1972,36 @@ class TestWebDriverPlaywrightAnimationWaitOrder: 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") @@ -1681,6 +2039,9 @@ class TestWebDriverPlaywrightAnimationWaitOrder: load_wait=30, animation_wait=2, 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)