update to have a to_log method so it's a 1 line change in tasks

Author: saponifi3d

src/sentry/workflow_engine/processors/workflow.py

@@ -591,40 +591,3 @@ def process_workflows(
 
     fire_actions(actions, detector, event_data)
     return WorkflowEvaluation(tainted=False, **extra_data)
-
-
-def process_workflows_with_logs(
-    batch_client: DelayedWorkflowClient,
-    event_data: WorkflowEventData,
-    event_start_time: datetime,
-    detector: Detector | None = None,
-) -> WorkflowEvaluation:
-    """
-    This method is used to create improved logging for `process_workflows`,
-    where we can capture the `WorkflowEvaluation` results, and log them.
-
-    This should create a log for each issue, so we can determine why a workflow
-    did or did not trigger.
-
-    TODO - further refactor the `process_actions` portion, to improve handling / logging.
-    """
-    from sentry.workflow_engine.processors.workflow import process_workflows
-
-    evaluation = process_workflows(batch_client, event_data, event_start_time, detector)
-
-    if isinstance(evaluation, WorkflowEvaluation):
-        # Attempted to evaluate, but no actions were triggered.
-
-        if evaluation.triggered_workflows is None:
-            # No workflow trigger conditions were met
-            logger.info(
-                "process_workflows.evaluation.workflow.not_triggered", extra=asdict(evaluation)
-            )
-        else:
-            # Workflow conditions met, but not action filters
-            logger.info("process_workflows.evaluation.workflow.triggered", extra=asdict(evaluation))
-    else:
-        # Workflow was fully processed, and actions were triggered
-        logger.info("process_workflows.evaluation.actions.triggered", extra=asdict(evaluation))
-
-    return evaluation

src/sentry/workflow_engine/tasks/workflows.py

@@ -45,7 +45,7 @@ def process_workflow_activity(activity_id: int, group_id: int, detector_id: int)
     The task will get the Activity from the database, create a WorkflowEventData object,
     and then process the data in `process_workflows`.
     """
-    from sentry.workflow_engine.processors.workflow import process_workflows_with_logs
+    from sentry.workflow_engine.processors.workflow import process_workflows
 
     with transaction.atomic(router.db_for_write(Detector)):
         try:
@@ -69,10 +69,12 @@ def process_workflow_activity(activity_id: int, group_id: int, detector_id: int)
     )
     with quiet_redis_noise():
         batch_client = DelayedWorkflowClient()
-        process_workflows_with_logs(
+        evaluation = process_workflows(
             batch_client, event_data, event_start_time=activity.datetime, detector=detector
         )
 
+    evaluation.to_log(logger)
+
     metrics.incr(
         "workflow_engine.tasks.process_workflows.activity_update.executed",
         tags={"activity_type": activity.type, "detector_type": detector.type},
@@ -104,7 +106,7 @@ def process_workflows_event(
     start_timestamp_seconds: float | None = None,
     **kwargs: dict[str, Any],
 ) -> None:
-    from sentry.workflow_engine.processors.workflow import process_workflows_with_logs
+    from sentry.workflow_engine.processors.workflow import process_workflows
 
     recorder = scopedstats.Recorder()
     start_time = time.time()
@@ -132,7 +134,11 @@ def process_workflows_event(
         )
         with quiet_redis_noise():
             batch_client = DelayedWorkflowClient()
-            process_workflows_with_logs(batch_client, event_data, event_start_time=event_start_time)
+            evaluation = process_workflows(
+                batch_client, event_data, event_start_time=event_start_time
+            )
+
+    evaluation.to_log(logger)
     duration = time.time() - start_time
     is_slow = duration > 1.0
     # We want full coverage for particularly slow cases, plus a random sampling.

src/sentry/workflow_engine/types.py

@@ -3,6 +3,7 @@
 from abc import ABC, abstractmethod
 from dataclasses import dataclass, field
 from enum import IntEnum, StrEnum
+from logging import Logger
 from typing import TYPE_CHECKING, Any, ClassVar, Generic, TypedDict, TypeVar
 
 from sentry.types.group import PriorityLevel
@@ -86,15 +87,48 @@ class WorkflowEvaluation:
 
     tainted: bool
 
-    group_event: GroupEvent | None = None
     message: str | None = None
 
+    # data: WorkflowProcessingContextData
+
+    group_event: GroupEvent | None = None
     actions: list[Action] | None = None
     workflows: list[Workflow] | None = None
     triggered_actions: list[Action] | None = None
     triggered_workflows: list[Workflow] | None = None
     associated_detectors: list[Detector] | None = None
 
+    def to_log(self, logger: Logger) -> None:
+        """
+        Determines how far in the process the evaluation got to
+        and creates a structured log string to quickly find.
+
+        Then this will return the that log string, and the
+        relevant processing data to be logged.
+        """
+        log_str = "workflow_engine.process_workflows.evaluation"
+
+        if self.tainted:
+            if self.triggered_workflows is None:
+                log_str = f"{log_str}.workflows.not_triggered"
+            else:
+                log_str = f"{log_str}.workflows.triggered"
+        else:
+            log_str = f"{log_str}.actions.triggered"
+
+        # TODO - simplify the extra data with context data class
+        logger.info(
+            log_str,
+            extra={
+                "group_event": self.group_event,
+                "actions": self.actions,
+                "triggered_actions": self.triggered_actions,
+                "workflows": self.workflows,
+                "triggered_workflows": self.triggered_workflows,
+                "associated_detectors": self.associated_detectors,
+            },
+        )
+
 
 class ConfigTransformer(ABC):
     """

tests/sentry/workflow_engine/processors/test_workflow.py

@@ -210,7 +210,6 @@ def test_same_environment_only(self) -> None:
 
         result = process_workflows(self.batch_client, self.event_data, FROZEN_TIME)
         assert result.triggered_workflows == {self.error_workflow, matching_env_workflow}
-        assert result.message == "No actions to evaluate; filtered or not triggered"
 
     def test_issue_occurrence_event(self) -> None:
         issue_occurrence = self.build_occurrence(evidence_data={"detector_id": self.detector.id})
@@ -235,9 +234,7 @@ def test_regressed_event(self) -> None:
         )
 
         result = process_workflows(self.batch_client, self.event_data, FROZEN_TIME)
-        assert result.tainted is True
         assert result.triggered_workflows == {self.error_workflow, workflow}
-        assert result.message == "No actions to evaluate; filtered or not triggered"
 
     @patch("sentry.utils.metrics.incr")
     @patch("sentry.workflow_engine.processors.detector.logger")

tests/sentry/workflow_engine/test_task.py

@@ -137,7 +137,8 @@ def setUp(self) -> None:
         self.activity.save()
         self.detector = self.create_detector(type=MetricIssue.slug)
 
-    def test_process_workflow_activity__no_workflows(self) -> None:
+    @mock.patch("sentry.workflow_engine.tasks.workflows.logger")
+    def test_process_workflow_activity__no_workflows(self, mock_logger) -> None:
         with mock.patch(
             "sentry.workflow_engine.processors.workflow.evaluate_workflow_triggers",
             return_value=set(),
@@ -150,6 +151,18 @@ def test_process_workflow_activity__no_workflows(self) -> None:
             # Short-circuit evaluation, no workflows associated
             assert mock_evaluate.call_count == 0
 
+            mock_logger.info.assert_called_once_with(
+                "workflow_engine.process_workflows.evaluation.workflows.not_triggered",
+                extra={
+                    "group_event": self.activity,
+                    "actions": None,
+                    "triggered_actions": None,
+                    "workflows": set(),
+                    "triggered_workflows": None,
+                    "associated_detectors": [self.detector],
+                },
+            )
+
     @mock.patch(
         "sentry.workflow_engine.processors.workflow.evaluate_workflow_triggers",
         return_value=(set(), {}),
@@ -158,8 +171,9 @@ def test_process_workflow_activity__no_workflows(self) -> None:
         "sentry.workflow_engine.processors.workflow.evaluate_workflows_action_filters",
         return_value=set(),
     )
+    @mock.patch("sentry.workflow_engine.tasks.workflows.logger")
     def test_process_workflow_activity__workflows__no_actions(
-        self, mock_eval_actions, mock_evaluate
+        self, mock_logger, mock_eval_actions, mock_evaluate
     ):
         self.workflow = self.create_workflow(organization=self.organization)
         self.create_detector_workflow(
@@ -181,8 +195,23 @@ def test_process_workflow_activity__workflows__no_actions(
         mock_evaluate.assert_called_once_with({self.workflow}, event_data, mock.ANY)
         assert mock_eval_actions.call_count == 0
 
+        mock_logger.info.assert_called_once_with(
+            "workflow_engine.process_workflows.evaluation.workflows.triggered",
+            extra={
+                "group_event": self.activity,
+                "actions": None,
+                "triggered_actions": None,
+                "workflows": {self.workflow},
+                "triggered_workflows": set(),  # from the mock
+                "associated_detectors": [self.detector],
+            },
+        )
+
     @mock.patch("sentry.workflow_engine.processors.action.filter_recently_fired_workflow_actions")
-    def test_process_workflow_activity(self, mock_filter_actions: mock.MagicMock) -> None:
+    @mock.patch("sentry.workflow_engine.tasks.workflows.logger")
+    def test_process_workflow_activity(
+        self, mock_logger, mock_filter_actions: mock.MagicMock
+    ) -> None:
         self.workflow = self.create_workflow(organization=self.organization)
 
         self.action_group = self.create_data_condition_group(logic_type="any-short")
@@ -210,6 +239,17 @@ def test_process_workflow_activity(self, mock_filter_actions: mock.MagicMock) ->
         )
 
         mock_filter_actions.assert_called_once_with({self.action_group}, expected_event_data)
+        mock_logger.info.assert_called_once_with(
+            "workflow_engine.process_workflows.evaluation.actions.triggered",
+            extra={
+                "group_event": self.activity,
+                "actions": {self.action_group},
+                "triggered_actions": mock_filter_actions(),  # the result of the mock
+                "workflows": {self.workflow},
+                "triggered_workflows": {self.workflow},
+                "associated_detectors": [self.detector],
+            },
+        )
 
     @mock.patch(
         "sentry.workflow_engine.models.incident_groupopenperiod.update_incident_based_on_open_period_status_change"