From aaa4a7b371a184b14608631b7ba17aa9b44d6ac1 Mon Sep 17 00:00:00 2001
From: Elizabeth Thompson <eschutho@gmail.com>
Date: Tue, 16 Jan 2024 14:44:30 -0800
Subject: [PATCH] feat: global logs context (#26418)

---
 superset/commands/report/execute.py           |   2 +
 superset/reports/notifications/slack.py       |   9 +-
 superset/utils/decorators.py                  |  82 ++++++++-
 tests/unit_tests/notifications/slack_tests.py |  86 +++++++++
 tests/unit_tests/utils/test_decorators.py     | 164 ++++++++++++++++++
 5 files changed, 341 insertions(+), 2 deletions(-)
 create mode 100644 tests/unit_tests/notifications/slack_tests.py

diff --git a/superset/commands/report/execute.py b/superset/commands/report/execute.py
index d4b53e30dd..349ef0c85b 100644
--- a/superset/commands/report/execute.py
+++ b/superset/commands/report/execute.py
@@ -71,6 +71,7 @@ from superset.tasks.utils import get_executor
 from superset.utils.celery import session_scope
 from superset.utils.core import HeaderDataType, override_user
 from superset.utils.csv import get_chart_csv_data, get_chart_dataframe
+from superset.utils.decorators import logs_context
 from superset.utils.screenshots import ChartScreenshot, DashboardScreenshot
 from superset.utils.urls import get_url_path
 
@@ -81,6 +82,7 @@ class BaseReportState:
     current_states: list[ReportState] = []
     initial: bool = False
 
+    @logs_context()
     def __init__(
         self,
         session: Session,
diff --git a/superset/reports/notifications/slack.py b/superset/reports/notifications/slack.py
index fbae398bc5..41ed2ceeb3 100644
--- a/superset/reports/notifications/slack.py
+++ b/superset/reports/notifications/slack.py
@@ -22,6 +22,7 @@ from typing import Union
 
 import backoff
 import pandas as pd
+from flask import g
 from flask_babel import gettext as __
 from slack_sdk import WebClient
 from slack_sdk.errors import (
@@ -175,6 +176,7 @@ Error: %(text)s
         channel = self._get_channel()
         body = self._get_body()
         file_type = "csv" if self._content.csv else "png"
+        global_logs_context = getattr(g, "logs_context", {}) or {}
         try:
             token = app.config["SLACK_API_TOKEN"]
             if callable(token):
@@ -192,7 +194,12 @@ Error: %(text)s
                     )
             else:
                 client.chat_postMessage(channel=channel, text=body)
-            logger.info("Report sent to slack")
+            logger.info(
+                "Report sent to slack",
+                extra={
+                    "execution_id": global_logs_context.get("execution_id"),
+                },
+            )
         except (
             BotUserAccessError,
             SlackRequestError,
diff --git a/superset/utils/decorators.py b/superset/utils/decorators.py
index 9c21e3b5ec..43b6909caf 100644
--- a/superset/utils/decorators.py
+++ b/superset/utils/decorators.py
@@ -16,16 +16,20 @@
 # under the License.
 from __future__ import annotations
 
+import logging
 import time
 from collections.abc import Iterator
 from contextlib import contextmanager
 from typing import Any, Callable, TYPE_CHECKING
+from uuid import UUID
 
-from flask import current_app, Response
+from flask import current_app, g, Response
 
 from superset.utils import core as utils
 from superset.utils.dates import now_as_float
 
+logger = logging.getLogger(__name__)
+
 if TYPE_CHECKING:
     from superset.stats_logger import BaseStatsLogger
 
@@ -61,6 +65,82 @@ def statsd_gauge(metric_prefix: str | None = None) -> Callable[..., Any]:
     return decorate
 
 
+def logs_context(
+    context_func: Callable[..., dict[Any, Any]] | None = None,
+    **ctx_kwargs: int | str | UUID | None,
+) -> Callable[..., Any]:
+    """
+    Takes arguments and adds them to the global logs_context.
+    This is for logging purposes only and values should not be relied on or mutated
+    """
+
+    def decorate(f: Callable[..., Any]) -> Callable[..., Any]:
+        def wrapped(*args: Any, **kwargs: Any) -> Any:
+            if not hasattr(g, "logs_context"):
+                g.logs_context = {}
+
+            # limit data that can be saved to logs_context
+            # in order to prevent antipatterns
+            available_logs_context_keys = [
+                "slice_id",
+                "dashboard_id",
+                "dataset_id",
+                "execution_id",
+                "report_schedule_id",
+            ]
+            # set value from kwargs from
+            # wrapper function if it exists
+            # e.g. @logs_context()
+            #      def my_func(slice_id=None, **kwargs)
+            #
+            #      my_func(slice_id=2)
+            logs_context_data = {
+                key: val
+                for key, val in kwargs.items()
+                if key in available_logs_context_keys
+                if val is not None
+            }
+
+            try:
+                # if keys are passed in to decorator directly, add them to logs_context
+                # by overriding values from kwargs
+                # e.g. @logs_context(slice_id=1, dashboard_id=1)
+                logs_context_data.update(
+                    {
+                        key: ctx_kwargs.get(key)
+                        for key in available_logs_context_keys
+                        if ctx_kwargs.get(key) is not None
+                    }
+                )
+
+                if context_func is not None:
+                    # if a context function is passed in, call it and add the
+                    # returned values to logs_context
+                    # context_func=lambda *args, **kwargs: {
+                    # "slice_id": 1, "dashboard_id": 1
+                    # }
+                    logs_context_data.update(
+                        {
+                            key: value
+                            for key, value in context_func(*args, **kwargs).items()
+                            if key in available_logs_context_keys
+                            if value is not None
+                        }
+                    )
+
+            except (TypeError, KeyError, AttributeError):
+                # do nothing if the key doesn't exist
+                # or context is not callable
+                logger.warning("Invalid data was passed to the logs context decorator")
+
+            g.logs_context.update(logs_context_data)
+            return f(*args, **kwargs)
+
+        return wrapped
+
+    return decorate
+
+
 @contextmanager
 def stats_timing(stats_key: str, stats_logger: BaseStatsLogger) -> Iterator[float]:
     """Provide a transactional scope around a series of operations."""
diff --git a/tests/unit_tests/notifications/slack_tests.py b/tests/unit_tests/notifications/slack_tests.py
new file mode 100644
index 0000000000..7e6cc3afc1
--- /dev/null
+++ b/tests/unit_tests/notifications/slack_tests.py
@@ -0,0 +1,86 @@
+# 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.
+import uuid
+from unittest.mock import MagicMock, patch
+
+import pandas as pd
+from flask import g
+
+
+@patch("superset.reports.notifications.slack.g")
+@patch("superset.reports.notifications.slack.logger")
+def test_send_slack(
+    logger_mock: MagicMock,
+    flask_global_mock: MagicMock,
+) -> None:
+    # `superset.models.helpers`, a dependency of following imports,
+    # requires app context
+    from superset.reports.models import ReportRecipients, ReportRecipientType
+    from superset.reports.notifications.base import NotificationContent
+    from superset.reports.notifications.slack import SlackNotification, WebClient
+
+    execution_id = uuid.uuid4()
+    flask_global_mock.logs_context = {"execution_id": execution_id}
+    content = NotificationContent(
+        name="test alert",
+        header_data={
+            "notification_format": "PNG",
+            "notification_type": "Alert",
+            "owners": [1],
+            "notification_source": None,
+            "chart_id": None,
+            "dashboard_id": None,
+        },
+        embedded_data=pd.DataFrame(
+            {
+                "A": [1, 2, 3],
+                "B": [4, 5, 6],
+                "C": ["111", "222", '<a href="http://www.example.com">333</a>'],
+            }
+        ),
+        description='<p>This is <a href="#">a test</a> alert</p><br />',
+    )
+    with patch.object(
+        WebClient, "chat_postMessage", return_value=True
+    ) as chat_post_message_mock:
+        SlackNotification(
+            recipient=ReportRecipients(
+                type=ReportRecipientType.SLACK,
+                recipient_config_json='{"target": "some_channel"}',
+            ),
+            content=content,
+        ).send()
+        logger_mock.info.assert_called_with(
+            "Report sent to slack", extra={"execution_id": execution_id}
+        )
+        chat_post_message_mock.assert_called_with(
+            channel="some_channel",
+            text="""*test alert*
+
+<p>This is <a href="#">a test</a> alert</p><br />
+
+<None|Explore in Superset>
+
+```
+|    |   A |   B | C                                        |
+|---:|----:|----:|:-----------------------------------------|
+|  0 |   1 |   4 | 111                                      |
+|  1 |   2 |   5 | 222                                      |
+|  2 |   3 |   6 | <a href="http://www.example.com">333</a> |
+```
+""",
+        )
diff --git a/tests/unit_tests/utils/test_decorators.py b/tests/unit_tests/utils/test_decorators.py
index f600334414..6cfe55b641 100644
--- a/tests/unit_tests/utils/test_decorators.py
+++ b/tests/unit_tests/utils/test_decorators.py
@@ -16,6 +16,7 @@
 # under the License.
 
 
+import uuid
 from contextlib import nullcontext
 from inspect import isclass
 from typing import Any, Optional
@@ -85,3 +86,166 @@ def test_statsd_gauge(
         with cm:
             my_func(response_value, 1, 2)
             mock.assert_called_once_with(expected_result, 1)
+
+
+@patch("superset.utils.decorators.g")
+def test_context_decorator(flask_g_mock) -> None:
+    @decorators.logs_context()
+    def myfunc(*args, **kwargs) -> str:
+        return "test"
+
+    @decorators.logs_context(slice_id=1, dashboard_id=1, execution_id=uuid.uuid4())
+    def myfunc_with_kwargs(*args, **kwargs) -> str:
+        return "test"
+
+    @decorators.logs_context(bad_context=1)
+    def myfunc_with_dissallowed_kwargs(*args, **kwargs) -> str:
+        return "test"
+
+    @decorators.logs_context(
+        context_func=lambda *args, **kwargs: {"slice_id": kwargs["chart_id"]}
+    )
+    def myfunc_with_context(*args, **kwargs) -> str:
+        return "test"
+
+    ### should not add any data to the global.logs_context scope
+    flask_g_mock.logs_context = {}
+    myfunc(1, 1)
+    assert flask_g_mock.logs_context == {}
+
+    ### should add dashboard_id to the global.logs_context scope
+    flask_g_mock.logs_context = {}
+    myfunc(1, 1, dashboard_id=1)
+    assert flask_g_mock.logs_context == {"dashboard_id": 1}
+
+    ### should add slice_id to the global.logs_context scope
+    flask_g_mock.logs_context = {}
+    myfunc(1, 1, slice_id=1)
+    assert flask_g_mock.logs_context == {"slice_id": 1}
+
+    ### should add execution_id to the global.logs_context scope
+    flask_g_mock.logs_context = {}
+    myfunc(1, 1, execution_id=1)
+    assert flask_g_mock.logs_context == {"execution_id": 1}
+
+    ### should add all three to the global.logs_context scope
+    flask_g_mock.logs_context = {}
+    myfunc(1, 1, dashboard_id=1, slice_id=1, execution_id=1)
+    assert flask_g_mock.logs_context == {
+        "dashboard_id": 1,
+        "slice_id": 1,
+        "execution_id": 1,
+    }
+
+    ### should overwrite existing values in the global.logs_context scope
+    flask_g_mock.logs_context = {"dashboard_id": 2, "slice_id": 2, "execution_id": 2}
+    myfunc(1, 1, dashboard_id=3, slice_id=3, execution_id=3)
+    assert flask_g_mock.logs_context == {
+        "dashboard_id": 3,
+        "slice_id": 3,
+        "execution_id": 3,
+    }
+
+    ### Test when g.logs_context already exists
+    flask_g_mock.logs_context = {"slice_id": 2, "dashboard_id": 2}
+    args = (3, 4)
+    kwargs = {"slice_id": 3, "dashboard_id": 3}
+    myfunc(*args, **kwargs)
+    assert flask_g_mock.logs_context == {"slice_id": 3, "dashboard_id": 3}
+
+    ### Test when kwargs contain additional keys
+    flask_g_mock.logs_context = {}
+    args = (1, 2)
+    kwargs = {
+        "slice_id": 1,
+        "dashboard_id": 1,
+        "dataset_id": 1,
+        "execution_id": 1,
+        "report_schedule_id": 1,
+        "extra_key": 1,
+    }
+    myfunc(*args, **kwargs)
+    assert flask_g_mock.logs_context == {
+        "slice_id": 1,
+        "dashboard_id": 1,
+        "dataset_id": 1,
+        "execution_id": 1,
+        "report_schedule_id": 1,
+    }
+
+    ### should not add a value that does not exist in the global.logs_context scope
+    flask_g_mock.logs_context = {}
+    myfunc_with_dissallowed_kwargs()
+    assert flask_g_mock.logs_context == {}
+
+    ### should be able to add values to the decorator function directly
+    flask_g_mock.logs_context = {}
+    myfunc_with_kwargs()
+    assert flask_g_mock.logs_context["dashboard_id"] == 1
+    assert flask_g_mock.logs_context["slice_id"] == 1
+    assert isinstance(flask_g_mock.logs_context["execution_id"], uuid.UUID)
+
+    ### should be able to add values to the decorator function directly
+    # and it will overwrite any kwargs passed into the decorated function
+    flask_g_mock.logs_context = {}
+    myfunc_with_kwargs(execution_id=4)
+
+    assert flask_g_mock.logs_context["dashboard_id"] == 1
+    assert flask_g_mock.logs_context["slice_id"] == 1
+    assert isinstance(flask_g_mock.logs_context["execution_id"], uuid.UUID)
+
+    ### should be able to pass a callable context to the decorator
+    flask_g_mock.logs_context = {}
+    myfunc_with_context(chart_id=1)
+    assert flask_g_mock.logs_context == {"slice_id": 1}
+
+    ### Test when context_func returns additional keys
+    # it should use the context_func values
+    flask_g_mock.logs_context = {}
+    args = (1, 2)
+    kwargs = {"slice_id": 1, "dashboard_id": 1}
+
+    @decorators.logs_context(
+        context_func=lambda *args, **kwargs: {
+            "slice_id": 2,
+            "dashboard_id": 2,
+            "dataset_id": 2,
+            "execution_id": 2,
+            "report_schedule_id": 2,
+            "extra_key": 2,
+        }
+    )
+    def myfunc_with_extra_keys_context(*args, **kwargs) -> str:
+        return "test"
+
+    myfunc_with_extra_keys_context(
+        *args,
+        **kwargs,
+    )
+    assert flask_g_mock.logs_context == {
+        "slice_id": 2,
+        "dashboard_id": 2,
+        "dataset_id": 2,
+        "execution_id": 2,
+        "report_schedule_id": 2,
+    }
+
+    ### Test when context_func does not return a dictionary
+    flask_g_mock.logs_context = {}
+
+    @decorators.logs_context(context_func=lambda: "foo")  # type: ignore
+    def myfunc_with_bad_return_value() -> str:
+        return "test"
+
+    myfunc_with_bad_return_value()
+    assert flask_g_mock.logs_context == {}
+
+    ### Test when context_func is not callable
+    flask_g_mock.logs_context = {}
+
+    @decorators.logs_context(context_func="foo")  # type: ignore
+    def context_func_not_callable() -> str:
+        return "test"
+
+    context_func_not_callable()
+    assert flask_g_mock.logs_context == {}