fix(API Usage): API usage notification emails fire at 90%/100% while org is far below plan limit

api/organisations/chargebee/chargebee.py

@@ -1,5 +1,4 @@
 import logging
-from contextlib import suppress
 from datetime import datetime
 from typing import Any
 
@@ -183,7 +182,7 @@ def get_subscription_metadata_from_id(
         logger.warning("Subscription id is empty or None")
         return None
 
-    with suppress(ChargebeeAPIError):
+    try:
         chargebee_result = chargebee_client.Subscription.retrieve(subscription_id)
         chargebee_subscription = _convert_chargebee_subscription_to_dictionary(
             chargebee_result.subscription
@@ -193,6 +192,12 @@ def get_subscription_metadata_from_id(
             chargebee_subscription,
             chargebee_result.customer.email,
         )
+    except ChargebeeAPIError:
+        log.warning(
+            "metadata.fetch_failed",
+            subscription__id=subscription_id,
+            exc_info=True,
+        )
 
     return None
 

api/organisations/constants.py

@@ -1,5 +1,11 @@
+from datetime import timedelta
+
 API_USAGE_ALERT_THRESHOLDS = [75, 90, 100, 120, 200, 300, 400, 500]
 API_USAGE_GRACE_PERIOD = 7
+# Chargebee plan limits are refreshed every 6h (see
+# `update_organisation_subscription_information_cache_recurring`). Anything
+# older than 2x that means the sync is failing, not just due for its next run.
+CHARGEBEE_CACHE_STALE_AFTER = timedelta(hours=12)
 ALERT_EMAIL_MESSAGE = (
     "Organisation %s has used %d seats which is over their plan limit of %d (plan: %s)"
 )

api/organisations/subscription_info_cache.py

@@ -1,6 +1,7 @@
 import typing
 from datetime import timedelta
 
+import structlog
 from django.conf import settings
 from django.utils import timezone
 
@@ -11,6 +12,8 @@
 from .models import Organisation, OrganisationSubscriptionInformationCache
 from .subscriptions.constants import CHARGEBEE, SubscriptionCacheEntity
 
+logger = structlog.get_logger("billing")
+
 OrganisationSubscriptionInformationCacheDict = typing.Dict[
     int, OrganisationSubscriptionInformationCache
 ]
@@ -139,9 +142,14 @@ def _update_caches_with_chargebee_data(  # type: ignore[no-untyped-def]
 
         metadata = get_subscription_metadata_from_id(subscription.subscription_id)
         if not metadata:
+            logger.warning(
+                "subscription_information_cache.chargebee_sync_skipped",
+                organisation__id=organisation.id,
+            )
             continue
 
         subscription_info_cache = organisation_info_cache_dict[organisation.id]
         subscription_info_cache.allowed_seats = metadata.seats
         subscription_info_cache.allowed_30d_api_calls = metadata.api_calls
         subscription_info_cache.chargebee_email = metadata.chargebee_email
+        subscription_info_cache.chargebee_updated_at = timezone.now()

api/organisations/task_helpers.py

@@ -16,10 +16,13 @@
     OrganisationAPIUsageNotification,
     OrganisationRole,
 )
-from organisations.subscriptions.constants import MAX_API_CALLS_IN_FREE_PLAN
+from organisations.subscriptions.constants import (
+    CHARGEBEE,
+    MAX_API_CALLS_IN_FREE_PLAN,
+)
 from users.models import FFAdminUser
 
-from .constants import API_USAGE_ALERT_THRESHOLDS
+from .constants import API_USAGE_ALERT_THRESHOLDS, CHARGEBEE_CACHE_STALE_AFTER
 
 logger = structlog.get_logger("api_usage")
 
@@ -127,6 +130,21 @@ def handle_api_usage_notification_for_organisation(organisation: Organisation) -
 
         allowed_api_calls = subscription_cache.allowed_30d_api_calls
 
+        if organisation.subscription.payment_method == CHARGEBEE and (
+            subscription_cache.chargebee_updated_at is None
+            or subscription_cache.chargebee_updated_at
+            < now - CHARGEBEE_CACHE_STALE_AFTER
+        ):
+            # allowed_30d_api_calls is only trustworthy if it's been recently
+            # synced from Chargebee — otherwise it may hold a stale limit and
+            # trip a false alert.
+            logger.warning(
+                "notification.stale_chargebee_cache",
+                organisation__id=organisation.id,
+                chargebee_updated_at=subscription_cache.chargebee_updated_at,
+            )
+            return
+
     openfeature_client = get_openfeature_client()
     # TODO: Default to get_total_events_count — https://github.com/Flagsmith/flagsmith/issues/6985
     if openfeature_client.get_boolean_value(

api/tests/unit/organisations/chargebee/test_unit_chargebee_chargebee.py

@@ -12,6 +12,7 @@
     Subscription as SubscriptionOps,
 )
 from pytest_mock import MockerFixture
+from pytest_structlog import StructuredLogCapture
 from pytz import UTC
 
 from organisations.chargebee import (  # type: ignore[attr-defined]
@@ -454,7 +455,7 @@ class MockException(Exception):
 
 
 def test_get_subscription_metadata_from_id__chargebee_api_error__returns_none(  # type: ignore[no-untyped-def]
-    mocker, chargebee_object_metadata
+    mocker, chargebee_object_metadata, log: StructuredLogCapture
 ) -> None:
     # Given
     mocked_chargebee = mocker.patch(
@@ -471,6 +472,14 @@ def test_get_subscription_metadata_from_id__chargebee_api_error__returns_none(
 
     # Then
     assert subscription_metadata is None
+    assert log.events == [
+        {
+            "level": "warning",
+            "event": "metadata.fetch_failed",
+            "subscription__id": subscription_id,
+            "exc_info": True,
+        }
+    ]
 
 
 @pytest.mark.parametrize(

api/tests/unit/organisations/test_unit_organisations_subscription_info_cache.py

@@ -4,6 +4,7 @@
 from django.utils import timezone
 from pytest_django.fixtures import SettingsWrapper
 from pytest_mock import MockerFixture
+from pytest_structlog import StructuredLogCapture
 from task_processor.task_run_method import TaskRunMethod
 
 from organisations.chargebee.metadata import ChargebeeObjMetadata
@@ -71,6 +72,7 @@ def test_update_caches__with_usage_data__populates_cache_correctly(  # type: ign
         organisation.subscription_information_cache.allowed_30d_api_calls
         == chargebee_metadata.api_calls
     )
+    assert organisation.subscription_information_cache.chargebee_updated_at == now
 
     mocked_get_subscription_metadata.assert_called_once_with(
         chargebee_subscription.subscription_id
@@ -84,6 +86,52 @@ def test_update_caches__with_usage_data__populates_cache_correctly(  # type: ign
     ]
 
 
+def test_update_caches__chargebee_sync_fails__leaves_allowed_calls_and_timestamp_unchanged(
+    mocker: MockerFixture,
+    organisation: Organisation,
+    chargebee_subscription: Subscription,
+    settings: SettingsWrapper,
+    log: StructuredLogCapture,
+) -> None:
+    # Given
+    settings.CHARGEBEE_API_KEY = "api-key"
+    settings.INFLUXDB_TOKEN = "token"
+    settings.TASK_RUN_METHOD = TaskRunMethod.SYNCHRONOUSLY
+
+    previously_synced_at = timezone.now() - timedelta(hours=6)
+    OrganisationSubscriptionInformationCache.objects.create(
+        organisation=organisation,
+        allowed_30d_api_calls=1_000_000,
+        chargebee_updated_at=previously_synced_at,
+    )
+
+    mocker.patch("organisations.subscription_info_cache.get_top_organisations")
+    mocker.patch(
+        "organisations.subscription_info_cache.get_subscription_metadata_from_id",
+        return_value=None,
+    )
+
+    # When
+    update_caches(SubscriptionCacheEntity.CHARGEBEE)
+
+    # Then
+    organisation.subscription_information_cache.refresh_from_db()
+    assert (
+        organisation.subscription_information_cache.allowed_30d_api_calls == 1_000_000
+    )
+    assert (
+        organisation.subscription_information_cache.chargebee_updated_at
+        == previously_synced_at
+    )
+    assert log.events == [
+        {
+            "level": "warning",
+            "event": "subscription_information_cache.chargebee_sync_skipped",
+            "organisation__id": organisation.id,
+        }
+    ]
+
+
 def test_update_caches__no_usage_data__resets_cache_to_zero(
     mocker: MockerFixture,
     organisation: Organisation,

api/tests/unit/organisations/test_unit_organisations_tasks.py

@@ -385,6 +385,108 @@ def test_handle_api_usage_notification_for_organisation__billing_starts_at_over_
     )
 
 
+def test_handle_api_usage_notification_for_organisation__chargebee_cache_never_synced__skips_notification(
+    organisation: Organisation,
+    log: StructuredLogCapture,
+    mocker: MockerFixture,
+) -> None:
+    # Given
+    now = timezone.now()
+    api_usage_mock = mocker.patch("organisations.task_helpers.get_current_api_usage")
+    organisation.subscription.plan = SCALE_UP
+    organisation.subscription.subscription_id = "fancy_id"
+    organisation.subscription.payment_method = CHARGEBEE
+    organisation.subscription.save()
+    OrganisationSubscriptionInformationCache.objects.create(
+        organisation=organisation,
+        allowed_30d_api_calls=100,
+        current_billing_term_starts_at=now - timedelta(days=45),
+        current_billing_term_ends_at=now + timedelta(days=320),
+        api_calls_30d=90,
+        chargebee_updated_at=None,
+    )
+
+    # When
+    handle_api_usage_notification_for_organisation(organisation)
+
+    # Then
+    api_usage_mock.assert_not_called()
+    assert log.events == [
+        {
+            "level": "warning",
+            "event": "notification.stale_chargebee_cache",
+            "organisation__id": organisation.id,
+            "chargebee_updated_at": None,
+        }
+    ]
+
+
+def test_handle_api_usage_notification_for_organisation__chargebee_cache_stale__skips_notification(
+    organisation: Organisation,
+    log: StructuredLogCapture,
+    mocker: MockerFixture,
+) -> None:
+    # Given
+    now = timezone.now()
+    stale_sync_at = now - timedelta(hours=13)
+    api_usage_mock = mocker.patch("organisations.task_helpers.get_current_api_usage")
+    organisation.subscription.plan = SCALE_UP
+    organisation.subscription.subscription_id = "fancy_id"
+    organisation.subscription.payment_method = CHARGEBEE
+    organisation.subscription.save()
+    OrganisationSubscriptionInformationCache.objects.create(
+        organisation=organisation,
+        allowed_30d_api_calls=100,
+        current_billing_term_starts_at=now - timedelta(days=45),
+        current_billing_term_ends_at=now + timedelta(days=320),
+        api_calls_30d=90,
+        chargebee_updated_at=stale_sync_at,
+    )
+
+    # When
+    handle_api_usage_notification_for_organisation(organisation)
+
+    # Then
+    api_usage_mock.assert_not_called()
+    assert log.events == [
+        {
+            "level": "warning",
+            "event": "notification.stale_chargebee_cache",
+            "organisation__id": organisation.id,
+            "chargebee_updated_at": stale_sync_at,
+        }
+    ]
+
+
+def test_handle_api_usage_notification_for_organisation__chargebee_cache_fresh__sends_notification(
+    organisation: Organisation,
+    mailoutbox: list[EmailMultiAlternatives],
+    mocker: MockerFixture,
+) -> None:
+    # Given
+    now = timezone.now()
+    mocker.patch("organisations.task_helpers.get_current_api_usage", return_value=91)
+    organisation.subscription.plan = SCALE_UP
+    organisation.subscription.subscription_id = "fancy_id"
+    organisation.subscription.payment_method = CHARGEBEE
+    organisation.subscription.save()
+    OrganisationSubscriptionInformationCache.objects.create(
+        organisation=organisation,
+        allowed_30d_api_calls=100,
+        current_billing_term_starts_at=now - timedelta(days=45),
+        current_billing_term_ends_at=now + timedelta(days=320),
+        api_calls_30d=90,
+        chargebee_updated_at=now - timedelta(hours=1),
+    )
+
+    # When
+    handle_api_usage_notification_for_organisation(organisation)
+
+    # Then
+    assert len(mailoutbox) == 1
+    assert mailoutbox[0].subject == "Flagsmith API use has reached 90%"
+
+
 @pytest.mark.freeze_time("2023-01-19T09:09:47.325132+00:00")
 def test_handle_api_usage_notifications__feature_flag_is_off__skips_processing(
     mocker: MockerFixture,

docs/docs/deployment-self-hosting/observability/_events-catalogue.md

@@ -2,7 +2,7 @@
 ### `api_usage.notification.evaluated`
 
 Logged at `info` from:
- - `api/organisations/task_helpers.py:153`
+ - `api/organisations/task_helpers.py:171`
 
 Attributes:
  - `allowed_api_calls`
@@ -16,20 +16,29 @@ Attributes:
 ### `api_usage.notification.missing_billing_starts_at`
 
 Logged at `error` from:
- - `api/organisations/task_helpers.py:118`
+ - `api/organisations/task_helpers.py:121`
 
 Attributes:
  - `organisation.id`
 
 ### `api_usage.notification.sent`
 
 Logged at `info` from:
- - `api/organisations/task_helpers.py:176`
+ - `api/organisations/task_helpers.py:194`
 
 Attributes:
  - `matched_threshold`
  - `organisation.id`
 
+### `api_usage.notification.stale_chargebee_cache`
+
+Logged at `warning` from:
+ - `api/organisations/task_helpers.py:141`
+
+Attributes:
+ - `chargebee_updated_at`
+ - `organisation.id`
+
 ### `app_analytics.no_analytics_database_configured`
 
 Logged at `warning` from:
@@ -40,10 +49,19 @@ Logged at `warning` from:
 Attributes:
  - `details`
 
+### `billing.metadata.fetch_failed`
+
+Logged at `warning` from:
+ - `api/organisations/chargebee/chargebee.py:196`
+
+Attributes:
+ - `exc_info`
+ - `subscription.id`
+
 ### `billing.seat.added`
 
 Logged at `info` from:
- - `api/organisations/chargebee/chargebee.py:239`
+ - `api/organisations/chargebee/chargebee.py:244`
 
 Attributes:
  - `addon.id`
@@ -52,6 +70,14 @@ Attributes:
  - `seats.previous`
  - `subscription.id`
 
+### `billing.subscription_information_cache.chargebee_sync_skipped`
+
+Logged at `warning` from:
+ - `api/organisations/subscription_info_cache.py:145`
+
+Attributes:
+ - `organisation.id`
+
 ### `code_references.cleanup_issues.created`
 
 Logged at `info` from: