Merge pull request #112 from reddit/re_raise_some_exceptions_and_add_metrics

Re-raise exceptions from `request_field_extractor` + prom metrics

Author: mrlevitas

docs/index.rst

@@ -39,8 +39,9 @@ Setup :code:`reddit-experiments` in your application's configuration file:
    ...
 
    # optional: a path to the file where experiment configuration is written
-   # (default: /var/local/experiments.json)
-   experiments.path = /var/local/foo.json
+   # default: /var/local/experiments.json
+   # note: production systems load the experiments.json file under nested `live-data/` dir
+   experiments.path = /var/local/live-data/experiments.json
 
    # optional: how long to wait for the experiments file to exist before failing
    # default:
@@ -50,7 +51,7 @@ Setup :code:`reddit-experiments` in your application's configuration file:
 
    # optional: the base amount of time for exponential backoff while waiting
    # for the file to be available.
-   # (default: no backoff time between tries)
+   # default: no backoff time between tries
    experiments.backoff = 1 second
 
    ...

pyproject.toml

@@ -1,3 +1,8 @@
 [tool.black]
 line-length = 100
 target-version = ['py36']
+
+[project]
+dynamic = ["version"]
+
+[tool.setuptools_scm]

reddit_decider/__init__.py

@@ -1,11 +1,13 @@
 import logging
+import sys
 
 from copy import deepcopy
 from dataclasses import dataclass
 from datetime import timedelta
 from enum import Enum
 from typing import Any
 from typing import Callable
+from typing import cast
 from typing import Dict
 from typing import IO
 from typing import List
@@ -30,6 +32,20 @@
 from rust_decider import ValueTypeMismatchException
 from typing_extensions import Literal
 
+from .prometheus_metrics import experiments_client_counter
+
+# get package's version for prometheus metrics
+if sys.version_info >= (3, 8):
+    from importlib.metadata import version as pkg_version, PackageNotFoundError
+else:
+    from importlib_metadata import version as pkg_version, PackageNotFoundError
+
+try:
+    # see https://github.com/python/mypy/issues/8823#issuecomment-1484368501
+    # for why cast is used (mypy)
+    _pkg_version = cast(Callable[[str], str], pkg_version)("reddit-experiments")
+except PackageNotFoundError:
+    _pkg_version = ""
 
 logger = logging.getLogger(__name__)
 
@@ -990,56 +1006,61 @@ def _minimal_decider(
         )
 
     def make_object_for_context(self, name: str, span: Span) -> Decider:
+        def inc_failure_counter(failure_type: str) -> None:
+            experiments_client_counter.labels(
+                operation="make_object_for_context",
+                success="false",
+                error_type=failure_type,
+                pkg_version=_pkg_version,
+            ).inc()
+
+        # initialize rust decider from watched manifest file
         rs_decider = None
         try:
             rs_decider = self._filewatcher.get_data()
         except WatchedFileNotAvailableError as exc:
+            inc_failure_counter("watched_file_not_available")
             logger.error(f"Experiment config file unavailable: {exc}")
 
+        # check for `span`'s presence
         if span is None:
+            inc_failure_counter("missing:'span'")
             logger.debug("`span` is `None` in reddit_decider `make_object_for_context()`.")
             return self._minimal_decider(internal=rs_decider, name=name, span=span)
 
-        request = None
+        # check for `span.context`'s presence
+        request = getattr(span, "context", None)
+
+        if request is None:
+            inc_failure_counter("missing:'span.context'")
+            return self._minimal_decider(
+                internal=rs_decider,
+                name=name,
+                span=span,
+            )
+
+        # extract fields from `span.context` if `self._request_field_extractor` is defined
         parsed_extracted_fields = None
         try:
-            request = span.context
-
             if self._request_field_extractor:
                 extracted_fields = self._request_field_extractor(request)
                 # prune any invalid keys/values
                 parsed_extracted_fields = self._prune_extracted_dict(
                     extracted_dict=extracted_fields
                 )
         except Exception as exc:
-            logger.info(
+            inc_failure_counter("request_field_extractor")
+            logger.error(
                 f"Unable to extract fields from `request_field_extractor()` in `make_object_for_context()`. details: {exc}"
             )
-
-        ec = None
-        try:
-            # if `edge_context` is inaccessible, bail early
-            if request is None:
-                return self._minimal_decider(
-                    internal=rs_decider,
-                    name=name,
-                    span=span,
-                    parsed_extracted_fields=parsed_extracted_fields,
-                )
-
-            ec = request.edge_context
-
-            if ec is None:
-                return self._minimal_decider(
-                    internal=rs_decider,
-                    name=name,
-                    span=span,
-                    parsed_extracted_fields=parsed_extracted_fields,
-                )
-        except Exception as exc:
-            logger.info(
-                f"Unable to access `request.edge_context` in `make_object_for_context()`. details: {exc}"
-            )
+            # re-raise exception raised by `_request_field_extractor`
+            # since it's user-defined & should be made visible
+            raise exc
+
+        ec = getattr(request, "edge_context", None)
+        # if `edge_context` is inaccessible, bail field extraction early
+        if ec is None:
+            inc_failure_counter("missing:'request.edge_context'")
             return self._minimal_decider(
                 internal=rs_decider,
                 name=name,
@@ -1048,7 +1069,6 @@ def make_object_for_context(self, name: str, span: Span) -> Decider:
             )
 
         # All fields below are derived from `edge_context`
-
         user_id = None
         logged_in = None
         cookie_created_timestamp = None
@@ -1139,6 +1159,7 @@ def make_object_for_context(self, name: str, span: Span) -> Decider:
                 extracted_fields=parsed_extracted_fields,
             )
         except Exception as exc:
+            inc_failure_counter("DeciderContext_init_failed")
             logger.warning(
                 f"Could not create full DeciderContext() (defaulting to empty DeciderContext()): {exc}"
             )

reddit_decider/prometheus_metrics.py

@@ -0,0 +1,7 @@
+from prometheus_client import Counter
+
+experiments_client_counter = Counter(
+    "experiments_py_client_total",
+    "Count of successful/failed Experiments.py operations (with error_type) in reddit-experiments package",
+    ["operation", "success", "error_type", "pkg_version"],
+)

requirements.txt

@@ -4,6 +4,7 @@ black==21.4b2
 reddit-decider==1.4.1
 flake8==3.9.1
 mypy==0.790
+prometheus-client>=0.12.0,<1.0
 pyramid==2.0   # required for `from baseplate.frameworks.pyramid import BaseplateRequest` which calls `import pyramid.events`
 pydocstyle==5.1.1
 pytest==6.2.5

tests/decider_tests.py

@@ -86,7 +86,6 @@ def setUp(self):
         super().setUp()
         self.event_logger = mock.Mock(spec=DebugLogger)
         self.mock_span = mock.MagicMock(spec=ServerSpan)
-        self.mock_span.context = None
 
     def test_make_client_without_timeout_set(self, file_watcher_mock):
         with create_temp_config_file({}) as f:
@@ -219,7 +218,8 @@ def test_make_object_for_context_and_decider_context(self):
         self.assertEqual(decider_event_dict["canonical_url"], CANONICAL_URL)
         self.assertEqual(decider_event_dict["request"]["canonical_url"], CANONICAL_URL)
 
-    def test_make_object_for_context_and_decider_context_without_span(self):
+    @mock.patch("reddit_decider.experiments_client_counter.labels")
+    def test_make_object_for_context_without_span(self, metric_counter_labels):
         with create_temp_config_file({}) as f:
             decider_ctx_factory = decider_client_from_config(
                 {"experiments.path": f.name, "experiments.timeout": "2 seconds"},
@@ -236,13 +236,56 @@ def test_make_object_for_context_and_decider_context_without_span(self):
             assert len(captured.records) == 1
             self.assertEqual(["WARNING:root:Dummy warning"], captured.output)
 
+            metric_counter_labels.assert_called_once_with(
+                operation="make_object_for_context",
+                success="false",
+                error_type="missing:'span'",
+                pkg_version=mock.ANY,
+            )
+
         self.assertIsInstance(decider, Decider)
 
         decider_ctx_dict = decider._decider_context.to_dict()
         self.assertEqual(decider_ctx_dict["user_id"], None)
 
-    def test_make_object_for_context_and_decider_context_with_broken_decider_field_extractor(self):
-        def broken_decider_field_extractor(_request: RequestContext):
+    @mock.patch("reddit_decider.experiments_client_counter.labels")
+    def test_make_object_for_context_with_span_context_as_None(self, metric_counter_labels):
+        with create_temp_config_file({}) as f:
+            decider_ctx_factory = decider_client_from_config(
+                {"experiments.path": f.name, "experiments.timeout": "2 seconds"},
+                self.event_logger,
+                prefix="experiments.",
+                request_field_extractor=decider_field_extractor,
+            )
+
+        mock_span = mock.MagicMock(spec=ServerSpan)
+        # span is missing context
+
+        with self.assertLogs(logger, logging.WARN) as captured:
+            # ensure no warnings are printed except for the dummy one
+            # https://stackoverflow.com/a/61381576/4260179
+            logger.warning("Dummy warning")
+
+            decider = decider_ctx_factory.make_object_for_context(name="test", span=mock_span)
+            assert len(captured.records) == 1
+            self.assertEqual(["WARNING:root:Dummy warning"], captured.output)
+
+            metric_counter_labels.assert_called_once_with(
+                operation="make_object_for_context",
+                success="false",
+                error_type="missing:'span.context'",
+                pkg_version=mock.ANY,
+            )
+
+        self.assertIsInstance(decider, Decider)
+
+        decider_ctx_dict = decider._decider_context.to_dict()
+        self.assertEqual(decider_ctx_dict["user_id"], None)
+
+    def test_make_object_for_context_and_decider_context_with_malformed_decider_field_extractor(
+        self,
+    ):
+        def decider_field_extractor_with_malformed_fields(_request: RequestContext):
             return {
                 "app_name": {},
                 "build_number": BUILD_NUMBER,
@@ -256,7 +299,7 @@ def broken_decider_field_extractor(_request: RequestContext):
                 {"experiments.path": f.name, "experiments.timeout": "2 seconds"},
                 self.event_logger,
                 prefix="experiments.",
-                request_field_extractor=broken_decider_field_extractor,
+                request_field_extractor=decider_field_extractor_with_malformed_fields,
             )
 
         with self.assertLogs() as captured:
@@ -280,6 +323,39 @@ def broken_decider_field_extractor(_request: RequestContext):
                 for x in captured.records
             )
 
+    @mock.patch("reddit_decider.experiments_client_counter.labels")
+    def test_make_object_for_context_with_broken_decider_field_extractor_raises_exception(
+        self, metric_counter_labels
+    ):
+        class SomeException(Exception):
+            pass
+
+        def broken_decider_field_extractor(_request: RequestContext):
+            raise SomeException("bad extractor")
+
+        with create_temp_config_file({}) as f:
+            decider_ctx_factory = decider_client_from_config(
+                {"experiments.path": f.name, "experiments.timeout": "2 seconds"},
+                self.event_logger,
+                prefix="experiments.",
+                request_field_extractor=broken_decider_field_extractor,
+            )
+
+        with self.assertRaises(SomeException) as e:
+            decider_ctx_factory.make_object_for_context(name="test", span=self.mock_span)
+
+        self.assertEqual(
+            str(e.exception),
+            "bad extractor",
+        )
+
+        metric_counter_labels.assert_called_once_with(
+            operation="make_object_for_context",
+            success="false",
+            error_type="request_field_extractor",
+            pkg_version=mock.ANY,
+        )
+
 
 # Todo: test DeciderClient()
 # @mock.patch("reddit_decider.FileWatcher")