From 78575a963f33ffdf928090b8d08297aed4022651 Mon Sep 17 00:00:00 2001 From: Deep Santoshwar Date: Tue, 28 Jul 2026 18:22:06 +0530 Subject: [PATCH] fix(API Usage): API usage notification emails fire at 90%/100% while org is far below plan limit The Chargebee-sourced allowed_30d_api_calls limit could go stale without anyone noticing: OrganisationSubscriptionInformationCache.chargebee_updated_at was never populated, and a failed Chargebee sync was silently swallowed with no logging. Once the cache held a lower limit than the org's real plan, usage-alert emails were computed against the wrong denominator and fired even though real usage was well under the actual limit. This logs Chargebee sync failures, stamps chargebee_updated_at on a successful sync, and skips (with a warning log) sending a usage alert for Chargebee-billed organisations whose cache hasn't synced recently, instead of trusting a limit that may be wrong. Closes #7976 --- api/organisations/chargebee/chargebee.py | 9 +- api/organisations/constants.py | 6 ++ api/organisations/subscription_info_cache.py | 8 ++ api/organisations/task_helpers.py | 22 +++- .../test_unit_chargebee_chargebee.py | 11 +- ...t_organisations_subscription_info_cache.py | 48 +++++++++ .../test_unit_organisations_tasks.py | 102 ++++++++++++++++++ .../observability/_events-catalogue.md | 34 +++++- 8 files changed, 231 insertions(+), 9 deletions(-) diff --git a/api/organisations/chargebee/chargebee.py b/api/organisations/chargebee/chargebee.py index 4e6437b6a647..eb13a5648e8e 100644 --- a/api/organisations/chargebee/chargebee.py +++ b/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 diff --git a/api/organisations/constants.py b/api/organisations/constants.py index 4cbdff0ba3fb..3c2ca777c5e4 100644 --- a/api/organisations/constants.py +++ b/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)" ) diff --git a/api/organisations/subscription_info_cache.py b/api/organisations/subscription_info_cache.py index 51b2c6e865c3..8d8972bff94f 100644 --- a/api/organisations/subscription_info_cache.py +++ b/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() diff --git a/api/organisations/task_helpers.py b/api/organisations/task_helpers.py index 0062633322dc..1fd91ab77ea3 100644 --- a/api/organisations/task_helpers.py +++ b/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( diff --git a/api/tests/unit/organisations/chargebee/test_unit_chargebee_chargebee.py b/api/tests/unit/organisations/chargebee/test_unit_chargebee_chargebee.py index 16f9ae9ef707..332a74717cbf 100644 --- a/api/tests/unit/organisations/chargebee/test_unit_chargebee_chargebee.py +++ b/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( diff --git a/api/tests/unit/organisations/test_unit_organisations_subscription_info_cache.py b/api/tests/unit/organisations/test_unit_organisations_subscription_info_cache.py index 2f8853ff4045..339f2b5ad87a 100644 --- a/api/tests/unit/organisations/test_unit_organisations_subscription_info_cache.py +++ b/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, diff --git a/api/tests/unit/organisations/test_unit_organisations_tasks.py b/api/tests/unit/organisations/test_unit_organisations_tasks.py index d953ed2845e3..d2cf95119a35 100644 --- a/api/tests/unit/organisations/test_unit_organisations_tasks.py +++ b/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, diff --git a/docs/docs/deployment-self-hosting/observability/_events-catalogue.md b/docs/docs/deployment-self-hosting/observability/_events-catalogue.md index cd06797f5cd7..e69aa2434d63 100644 --- a/docs/docs/deployment-self-hosting/observability/_events-catalogue.md +++ b/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,7 +16,7 @@ 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` @@ -24,12 +24,21 @@ Attributes: ### `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: