feat(alerts & reports): Easier to read execution logs (#13752)

* Prep for migration

* Migration for execution id column

* Generate execution ids for alerts and reports

* Change execution id range

* Add execution id to API endpoint

* Add execution id to execution log view

* Change execution id range

* Change execution id to a uuid

* Fix execution id type

* Switch state and exec. id columns

* Change db column to UUIDType

* Python lint

* Fix failing frontend tests

* execution_id -> uuid

* Fix migration head

* lint

* Use celery task id as the execution id

* lint

* lint for real

* Fix tests

superset-frontend/spec/javascripts/views/CRUD/alert/ExecutionLog_spec.jsx

@@ -43,6 +43,7 @@ const mockannotations = [...new Array(3)].map((_, i) => ({
   start_dttm: new Date().toISOString,
   state: 'Success',
   value: `report ${i} value`,
+  uuid: 'f44da495-b067-4645-b463-3be98d5f3206',
 }));
 
 fetchMock.get(executionLogsEndpoint, {

superset-frontend/src/views/CRUD/alert/ExecutionLog.tsx

@@ -95,6 +95,17 @@ function ExecutionLog({ addDangerToast, isReportEnabled }: ExecutionLogProps) {
         size: 'xs',
         disableSortBy: true,
       },
+      {
+        Cell: ({
+          row: {
+            original: { uuid: executionId },
+          },
+        }: any) => executionId.slice(0, 6),
+        accessor: 'uuid',
+        Header: t('Execution ID'),
+        size: 'xs',
+        disableSortBy: true,
+      },
       {
         Cell: ({
           row: {

superset-frontend/src/views/CRUD/alert/types.ts

@@ -91,6 +91,7 @@ export type LogObject = {
   start_dttm: string;
   state: string;
   value: string;
+  uuid: string;
 };
 
 export enum AlertState {

superset/migrations/versions/301362411006_add_execution_id_to_report_execution_.py

@@ -0,0 +1,39 @@
+# 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.
+"""add_execution_id_to_report_execution_log_model.py
+
+Revision ID: 301362411006
+Revises: 989bbe479899
+Create Date: 2021-03-23 05:23:15.641856
+
+"""
+
+# revision identifiers, used by Alembic.
+revision = "301362411006"
+down_revision = "989bbe479899"
+
+import sqlalchemy as sa
+from alembic import op
+from sqlalchemy_utils import UUIDType
+
+
+def upgrade():
+    op.add_column("report_execution_log", sa.Column("uuid", UUIDType(binary=True)))
+
+
+def downgrade():
+    op.drop_column("report_execution_log", "execution_id")

superset/models/reports.py

@@ -33,6 +33,7 @@ from sqlalchemy import (
 )
 from sqlalchemy.orm import backref, relationship
 from sqlalchemy.schema import UniqueConstraint
+from sqlalchemy_utils import UUIDType
 
 from superset.extensions import security_manager
 from superset.models.core import Database
@@ -171,6 +172,7 @@ class ReportExecutionLog(Model):  # pylint: disable=too-few-public-methods
 
     __tablename__ = "report_execution_log"
     id = Column(Integer, primary_key=True)
+    uuid = Column(UUIDType(binary=True))
 
     # Timestamps
     scheduled_dttm = Column(DateTime, nullable=False)

superset/reports/commands/execute.py

@@ -17,6 +17,7 @@
 import logging
 from datetime import datetime, timedelta
 from typing import Any, List, Optional
+from uuid import UUID
 
 from celery.exceptions import SoftTimeLimitExceeded
 from flask_appbuilder.security.sqla.models import User
@@ -73,11 +74,13 @@ class BaseReportState:
         session: Session,
         report_schedule: ReportSchedule,
         scheduled_dttm: datetime,
+        execution_id: UUID,
     ) -> None:
         self._session = session
         self._report_schedule = report_schedule
         self._scheduled_dttm = scheduled_dttm
         self._start_dttm = datetime.utcnow()
+        self._execution_id = execution_id
 
     def set_state_and_log(
         self, state: ReportState, error_message: Optional[str] = None,
@@ -117,6 +120,7 @@ class BaseReportState:
             state=state,
             error_message=error_message,
             report_schedule=self._report_schedule,
+            uuid=self._execution_id,
         )
         self._session.add(log)
         self._session.commit()
@@ -397,10 +401,12 @@ class ReportScheduleStateMachine:  # pylint: disable=too-few-public-methods
     def __init__(
         self,
         session: Session,
+        task_uuid: UUID,
         report_schedule: ReportSchedule,
         scheduled_dttm: datetime,
     ):
         self._session = session
+        self._execution_id = task_uuid
         self._report_schedule = report_schedule
         self._scheduled_dttm = scheduled_dttm
 
@@ -411,7 +417,10 @@ class ReportScheduleStateMachine:  # pylint: disable=too-few-public-methods
                 self._report_schedule.last_state in state_cls.current_states
             ):
                 state_cls(
-                    self._session, self._report_schedule, self._scheduled_dttm
+                    self._session,
+                    self._report_schedule,
+                    self._scheduled_dttm,
+                    self._execution_id,
                 ).next()
                 state_found = True
                 break
@@ -426,10 +435,11 @@ class AsyncExecuteReportScheduleCommand(BaseCommand):
     - On Alerts uses related Command AlertCommand and sends configured notifications
     """
 
-    def __init__(self, model_id: int, scheduled_dttm: datetime):
+    def __init__(self, task_id: str, model_id: int, scheduled_dttm: datetime):
         self._model_id = model_id
         self._model: Optional[ReportSchedule] = None
         self._scheduled_dttm = scheduled_dttm
+        self._execution_id = UUID(task_id)
 
     def run(self) -> None:
         with session_scope(nullpool=True) as session:
@@ -438,7 +448,7 @@ class AsyncExecuteReportScheduleCommand(BaseCommand):
                 if not self._model:
                     raise ReportScheduleExecuteUnexpectedError()
                 ReportScheduleStateMachine(
-                    session, self._model, self._scheduled_dttm
+                    session, self._execution_id, self._model, self._scheduled_dttm
                 ).run()
             except CommandException as ex:
                 raise ex

superset/reports/logs/api.py

@@ -49,6 +49,7 @@ class ReportExecutionLogRestApi(BaseSupersetModelRestApi):
         "value_row_json",
         "state",
         "error_message",
+        "uuid",
     ]
     list_columns = [
         "id",
@@ -59,6 +60,7 @@ class ReportExecutionLogRestApi(BaseSupersetModelRestApi):
         "value_row_json",
         "state",
         "error_message",
+        "uuid",
     ]
     order_columns = [
         "state",

superset/tasks/scheduler.py

@@ -63,8 +63,11 @@ def scheduler() -> None:
 @celery_app.task(name="reports.execute")
 def execute(report_schedule_id: int, scheduled_dttm: str) -> None:
     try:
+        task_id = execute.request.id
         scheduled_dttm_ = parser.parse(scheduled_dttm)
-        AsyncExecuteReportScheduleCommand(report_schedule_id, scheduled_dttm_).run()
+        AsyncExecuteReportScheduleCommand(
+            task_id, report_schedule_id, scheduled_dttm_,
+        ).run()
     except ReportScheduleUnexpectedError as ex:
         logger.error("An unexpected occurred while executing the report: %s", ex)
     except CommandException as ex:

tests/reports/commands_tests.py

@@ -18,6 +18,7 @@ import json
 from datetime import datetime, timedelta
 from typing import List, Optional
 from unittest.mock import Mock, patch
+from uuid import uuid4
 
 import pytest
 from contextlib2 import contextmanager
@@ -64,6 +65,8 @@ pytestmark = pytest.mark.usefixtures(
     "load_world_bank_dashboard_with_slices_module_scope"
 )
 
+test_id = str(uuid4())
+
 
 def get_target_from_report_schedule(report_schedule: ReportSchedule) -> List[str]:
     return [
@@ -518,7 +521,7 @@ def test_email_chart_report_schedule(
 
     with freeze_time("2020-01-01T00:00:00Z"):
         AsyncExecuteReportScheduleCommand(
-            create_report_email_chart.id, datetime.utcnow()
+            test_id, create_report_email_chart.id, datetime.utcnow()
         ).run()
 
         notification_targets = get_target_from_report_schedule(
@@ -556,7 +559,7 @@ def test_email_dashboard_report_schedule(
 
     with freeze_time("2020-01-01T00:00:00Z"):
         AsyncExecuteReportScheduleCommand(
-            create_report_email_dashboard.id, datetime.utcnow()
+            test_id, create_report_email_dashboard.id, datetime.utcnow()
         ).run()
 
         notification_targets = get_target_from_report_schedule(
@@ -588,7 +591,7 @@ def test_slack_chart_report_schedule(
 
     with freeze_time("2020-01-01T00:00:00Z"):
         AsyncExecuteReportScheduleCommand(
-            create_report_slack_chart.id, datetime.utcnow()
+            test_id, create_report_slack_chart.id, datetime.utcnow()
         ).run()
 
         notification_targets = get_target_from_report_schedule(
@@ -608,7 +611,7 @@ def test_report_schedule_not_found(create_report_slack_chart):
     """
     max_id = db.session.query(func.max(ReportSchedule.id)).scalar()
     with pytest.raises(ReportScheduleNotFoundError):
-        AsyncExecuteReportScheduleCommand(max_id + 1, datetime.utcnow()).run()
+        AsyncExecuteReportScheduleCommand(test_id, max_id + 1, datetime.utcnow()).run()
 
 
 @pytest.mark.usefixtures("create_report_slack_chart_working")
@@ -620,7 +623,7 @@ def test_report_schedule_working(create_report_slack_chart_working):
     with freeze_time("2020-01-01T00:00:00Z"):
         with pytest.raises(ReportSchedulePreviousWorkingError):
             AsyncExecuteReportScheduleCommand(
-                create_report_slack_chart_working.id, datetime.utcnow()
+                test_id, create_report_slack_chart_working.id, datetime.utcnow()
             ).run()
 
         assert_log(
@@ -643,7 +646,7 @@ def test_report_schedule_working_timeout(create_report_slack_chart_working):
     with freeze_time(current_time):
         with pytest.raises(ReportScheduleWorkingTimeoutError):
             AsyncExecuteReportScheduleCommand(
-                create_report_slack_chart_working.id, datetime.utcnow()
+                test_id, create_report_slack_chart_working.id, datetime.utcnow()
             ).run()
 
     # Only needed for MySQL, understand why
@@ -668,7 +671,7 @@ def test_report_schedule_success_grace(create_alert_slack_chart_success):
 
     with freeze_time(current_time):
         AsyncExecuteReportScheduleCommand(
-            create_alert_slack_chart_success.id, datetime.utcnow()
+            test_id, create_alert_slack_chart_success.id, datetime.utcnow()
         ).run()
 
     db.session.commit()
@@ -687,7 +690,7 @@ def test_report_schedule_success_grace_end(create_alert_slack_chart_grace):
 
     with freeze_time(current_time):
         AsyncExecuteReportScheduleCommand(
-            create_alert_slack_chart_grace.id, datetime.utcnow()
+            test_id, create_alert_slack_chart_grace.id, datetime.utcnow()
         ).run()
 
     db.session.commit()
@@ -711,7 +714,7 @@ def test_alert_limit_is_applied(screenshot_mock, email_mock, create_alert_email_
             return_value=None,
         ) as fetch_data_mock:
             AsyncExecuteReportScheduleCommand(
-                create_alert_email_chart.id, datetime.utcnow()
+                test_id, create_alert_email_chart.id, datetime.utcnow()
             ).run()
             assert "LIMIT 2" in execute_mock.call_args[0][1]
 
@@ -736,7 +739,7 @@ def test_email_dashboard_report_fails(
 
     with pytest.raises(ReportScheduleNotificationError):
         AsyncExecuteReportScheduleCommand(
-            create_report_email_dashboard.id, datetime.utcnow()
+            test_id, create_report_email_dashboard.id, datetime.utcnow()
         ).run()
 
     assert_log(ReportState.ERROR, error_message="Could not connect to SMTP XPTO")
@@ -757,7 +760,7 @@ def test_slack_chart_alert(screenshot_mock, email_mock, create_alert_email_chart
 
     with freeze_time("2020-01-01T00:00:00Z"):
         AsyncExecuteReportScheduleCommand(
-            create_alert_email_chart.id, datetime.utcnow()
+            test_id, create_alert_email_chart.id, datetime.utcnow()
         ).run()
 
         notification_targets = get_target_from_report_schedule(create_alert_email_chart)
@@ -789,7 +792,7 @@ def test_slack_token_callable_chart_report(
 
     with freeze_time("2020-01-01T00:00:00Z"):
         AsyncExecuteReportScheduleCommand(
-            create_report_slack_chart.id, datetime.utcnow()
+            test_id, create_report_slack_chart.id, datetime.utcnow()
         ).run()
         app.config["SLACK_API_TOKEN"].assert_called_once()
         assert slack_client_mock_class.called_with(token="cool_code", proxy="")
@@ -803,7 +806,7 @@ def test_email_chart_no_alert(create_no_alert_email_chart):
     """
     with freeze_time("2020-01-01T00:00:00Z"):
         AsyncExecuteReportScheduleCommand(
-            create_no_alert_email_chart.id, datetime.utcnow()
+            test_id, create_no_alert_email_chart.id, datetime.utcnow()
         ).run()
     assert_log(ReportState.NOOP)
 
@@ -818,7 +821,7 @@ def test_email_mul_alert(create_mul_alert_email_chart):
             (AlertQueryMultipleRowsError, AlertQueryMultipleColumnsError)
         ):
             AsyncExecuteReportScheduleCommand(
-                create_mul_alert_email_chart.id, datetime.utcnow()
+                test_id, create_mul_alert_email_chart.id, datetime.utcnow()
             ).run()
 
 
@@ -839,7 +842,7 @@ def test_soft_timeout_alert(email_mock, create_alert_email_chart):
         execute_mock.side_effect = SoftTimeLimitExceeded()
         with pytest.raises(AlertQueryTimeout):
             AsyncExecuteReportScheduleCommand(
-                create_alert_email_chart.id, datetime.utcnow()
+                test_id, create_alert_email_chart.id, datetime.utcnow()
             ).run()
 
     notification_targets = get_target_from_report_schedule(create_alert_email_chart)
@@ -866,7 +869,7 @@ def test_soft_timeout_screenshot(screenshot_mock, email_mock, create_alert_email
     screenshot_mock.side_effect = SoftTimeLimitExceeded()
     with pytest.raises(ReportScheduleScreenshotTimeout):
         AsyncExecuteReportScheduleCommand(
-            create_alert_email_chart.id, datetime.utcnow()
+            test_id, create_alert_email_chart.id, datetime.utcnow()
         ).run()
 
     notification_targets = get_target_from_report_schedule(create_alert_email_chart)
@@ -893,7 +896,7 @@ def test_fail_screenshot(screenshot_mock, email_mock, create_alert_email_chart):
     screenshot_mock.side_effect = Exception("Unexpected error")
     with pytest.raises(ReportScheduleScreenshotFailedError):
         AsyncExecuteReportScheduleCommand(
-            create_alert_email_chart.id, datetime.utcnow()
+            test_id, create_alert_email_chart.id, datetime.utcnow()
         ).run()
 
     notification_targets = get_target_from_report_schedule(create_alert_email_chart)
@@ -914,7 +917,7 @@ def test_invalid_sql_alert(email_mock, create_invalid_sql_alert_email_chart):
     with freeze_time("2020-01-01T00:00:00Z"):
         with pytest.raises((AlertQueryError, AlertQueryInvalidTypeError)):
             AsyncExecuteReportScheduleCommand(
-                create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+                test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
             ).run()
 
         notification_targets = get_target_from_report_schedule(
@@ -933,7 +936,7 @@ def test_grace_period_error(email_mock, create_invalid_sql_alert_email_chart):
     with freeze_time("2020-01-01T00:00:00Z"):
         with pytest.raises((AlertQueryError, AlertQueryInvalidTypeError)):
             AsyncExecuteReportScheduleCommand(
-                create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+                test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
             ).run()
 
         # Only needed for MySQL, understand why
@@ -950,7 +953,7 @@ def test_grace_period_error(email_mock, create_invalid_sql_alert_email_chart):
     with freeze_time("2020-01-01T00:30:00Z"):
         with pytest.raises((AlertQueryError, AlertQueryInvalidTypeError)):
             AsyncExecuteReportScheduleCommand(
-                create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+                test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
             ).run()
         db.session.commit()
         assert (
@@ -961,7 +964,7 @@ def test_grace_period_error(email_mock, create_invalid_sql_alert_email_chart):
     with freeze_time("2020-01-01T01:30:00Z"):
         with pytest.raises((AlertQueryError, AlertQueryInvalidTypeError)):
             AsyncExecuteReportScheduleCommand(
-                create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+                test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
             ).run()
         db.session.commit()
         assert (
@@ -981,7 +984,7 @@ def test_grace_period_error_flap(
     with freeze_time("2020-01-01T00:00:00Z"):
         with pytest.raises((AlertQueryError, AlertQueryInvalidTypeError)):
             AsyncExecuteReportScheduleCommand(
-                create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+                test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
             ).run()
         db.session.commit()
         # Assert we have 1 notification sent on the log
@@ -992,7 +995,7 @@ def test_grace_period_error_flap(
     with freeze_time("2020-01-01T00:30:00Z"):
         with pytest.raises((AlertQueryError, AlertQueryInvalidTypeError)):
             AsyncExecuteReportScheduleCommand(
-                create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+                test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
             ).run()
         db.session.commit()
         assert (
@@ -1008,11 +1011,11 @@ def test_grace_period_error_flap(
     with freeze_time("2020-01-01T00:31:00Z"):
         # One success
         AsyncExecuteReportScheduleCommand(
-            create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+            test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
         ).run()
         # Grace period ends
         AsyncExecuteReportScheduleCommand(
-            create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+            test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
         ).run()
 
         db.session.commit()
@@ -1027,7 +1030,7 @@ def test_grace_period_error_flap(
     with freeze_time("2020-01-01T00:32:00Z"):
         with pytest.raises((AlertQueryError, AlertQueryInvalidTypeError)):
             AsyncExecuteReportScheduleCommand(
-                create_invalid_sql_alert_email_chart.id, datetime.utcnow()
+                test_id, create_invalid_sql_alert_email_chart.id, datetime.utcnow()
             ).run()
         db.session.commit()
         assert (