chore(logs): Add is_cached in sync AND async results (apache#36102)

Author: Antonio-RiveroMartnez

superset/charts/data/api.py

@@ -171,7 +171,7 @@ def get_data(  # noqa: C901
             and query_context.result_format == ChartDataResultFormat.JSON
             and query_context.result_type == ChartDataResultType.FULL
         ):
-            return self._run_async(json_body, command)
+            return self._run_async(json_body, command, add_extra_log_payload)
 
         try:
             form_data = json.loads(chart.params)
@@ -265,7 +265,7 @@ def data(  # noqa: C901
             and query_context.result_format == ChartDataResultFormat.JSON
             and query_context.result_type == ChartDataResultType.FULL
         ):
-            return self._run_async(json_body, command)
+            return self._run_async(json_body, command, add_extra_log_payload)
 
         form_data = json_body.get("form_data")
         return self._get_data_response(
@@ -334,7 +334,10 @@ def data_from_cache(self, cache_key: str) -> Response:
         return self._get_data_response(command, True)
 
     def _run_async(
-        self, form_data: dict[str, Any], command: ChartDataCommand
+        self,
+        form_data: dict[str, Any],
+        command: ChartDataCommand,
+        add_extra_log_payload: Callable[..., None] | None = None,
     ) -> Response:
         """
         Execute command as an async query.
@@ -343,6 +346,10 @@ def _run_async(
         with contextlib.suppress(ChartDataCacheLoadError):
             result = command.run(force_cached=True)
             if result is not None:
+                # Log is_cached if extra payload callback is provided.
+                # This indicates no async job was triggered - data was already cached
+                # and a synchronous response is being returned immediately.
+                self._log_is_cached(result, add_extra_log_payload)
                 return self._send_chart_response(result)
         # Otherwise, kick off a background job to run the chart query.
         # Clients will either poll or be notified of query completion,
@@ -424,6 +431,25 @@ def _process_data(query_data: Any) -> Any:
 
         return self.response_400(message=f"Unsupported result_format: {result_format}")
 
+    def _log_is_cached(
+        self,
+        result: dict[str, Any],
+        add_extra_log_payload: Callable[..., None] | None,
+    ) -> None:
+        """
+        Log is_cached values from query results to event logger.
+
+        Extracts is_cached from each query in the result and logs it.
+        If there's a single query, logs the boolean value directly.
+        If multiple queries, logs as a list.
+        """
+        if add_extra_log_payload and result and "queries" in result:
+            is_cached_values = [query.get("is_cached") for query in result["queries"]]
+            if len(is_cached_values) == 1:
+                add_extra_log_payload(is_cached=is_cached_values[0])
+            elif is_cached_values:
+                add_extra_log_payload(is_cached=is_cached_values)
+
     @event_logger.log_this
     def _get_data_response(
         self,
@@ -442,12 +468,7 @@ def _get_data_response(
             return self.response_400(message=exc.message)
 
         # Log is_cached if extra payload callback is provided
-        if add_extra_log_payload and result and "queries" in result:
-            is_cached_values = [query.get("is_cached") for query in result["queries"]]
-            if len(is_cached_values) == 1:
-                add_extra_log_payload(is_cached=is_cached_values[0])
-            elif is_cached_values:
-                add_extra_log_payload(is_cached=is_cached_values)
+        self._log_is_cached(result, add_extra_log_payload)
 
         return self._send_chart_response(result, form_data, datasource)
 

tests/integration_tests/charts/data/api_tests.py

@@ -753,10 +753,11 @@ def test_chart_data_async(self):
 
     @with_feature_flags(GLOBAL_ASYNC_QUERIES=True)
     @pytest.mark.usefixtures("load_birth_names_dashboard_with_slices")
-    def test_chart_data_async_cached_sync_response(self):
+    @mock.patch("superset.extensions.event_logger.log")
+    def test_chart_data_async_cached_sync_response(self, mock_event_logger):
         """
         Chart data API: Test chart data query returns results synchronously
-        when results are already cached.
+        when results are already cached, and that is_cached is logged.
         """
         app._got_first_request = False
         async_query_manager_factory.init_app(app)
@@ -767,7 +768,7 @@ class QueryContext:
 
         cmd_run_val = {
             "query_context": QueryContext(),
-            "queries": [{"query": "select * from foo"}],
+            "queries": [{"query": "select * from foo", "is_cached": True}],
         }
 
         with mock.patch.object(
@@ -780,7 +781,16 @@ class QueryContext:
             assert rv.status_code == 200
             data = json.loads(rv.data.decode("utf-8"))
             patched_run.assert_called_once_with(force_cached=True)
-            assert data == {"result": [{"query": "select * from foo"}]}
+            assert data == {
+                "result": [{"query": "select * from foo", "is_cached": True}]
+            }
+
+            # Verify that is_cached was logged to event logger
+            call_kwargs = mock_event_logger.call_args[1]
+            records = call_kwargs.get("records", [])
+            assert len(records) > 0
+            # is_cached should be True when retrieved from cache in async path
+            assert records[0]["is_cached"] is True
 
     @pytest.mark.usefixtures("load_birth_names_dashboard_with_slices")
     @mock.patch("superset.extensions.event_logger.log")