fix: Log the cached-data evaluation warning only once per client

ldclient/async_client.py

@@ -91,6 +91,11 @@ def __init__(self, config: AsyncConfig):
         self._event_factory_default = EventFactory(False)
         self._event_factory_with_reasons = EventFactory(True)
 
+        # One event loop runs the client. No await separates the check and the set of
+        # these flags, so plain booleans are safe.
+        self._eval_cached_data_warned = False
+        self._all_flags_cached_data_warned = False
+
         # Build the object graph here (loop-free). start() supplies the loop-bound
         # resources: the HTTP session (created lazily), the data source, the
         # big-segment poll, and the event processor. Evaluation before start()
@@ -496,7 +501,9 @@ async def _evaluate_internal(self, key: str, context: Context, default: Any, eve
         availability = await self._data_system.data_availability()
         if availability != DataAvailability.REFRESHED:
             if availability == DataAvailability.CACHED:
-                log.warning("Feature Flag evaluation attempted before client has initialized - using last known values from feature store for feature key: " + key)
+                if not self._eval_cached_data_warned:
+                    self._eval_cached_data_warned = True
+                    log.warning("Feature Flag evaluation attempted before client has initialized - using last known values from feature store for feature key: " + key + ". This message is logged once.")
             else:
                 log.warning("Feature Flag evaluation attempted before client has initialized! Feature store unavailable - returning default: " + str(default) + " for feature key: " + key)
                 reason = error_reason('CLIENT_NOT_READY')
@@ -568,7 +575,9 @@ async def all_flags_state(self, context: Context, **kwargs) -> FeatureFlagsState
         availability = await self._data_system.data_availability()
         if availability != DataAvailability.REFRESHED:
             if availability == DataAvailability.CACHED:
-                log.warning("all_flags_state() called before client has finished initializing! Using last known values from feature store")
+                if not self._all_flags_cached_data_warned:
+                    self._all_flags_cached_data_warned = True
+                    log.warning("all_flags_state() called before client has finished initializing! Using last known values from feature store. This message is logged once.")
             else:
                 log.warning("all_flags_state() called before client has finished initializing! Feature store unavailable - returning empty state")
                 return FeatureFlagsState(False)

ldclient/client.py

@@ -78,6 +78,12 @@ def __init__(self, config: Config, start_wait: float = 5):
         self._event_factory_default = EventFactory(False)
         self._event_factory_with_reasons = EventFactory(True)
 
+        # Python has no lock-free atomic flag in the standard library. Code reaches this
+        # lock only when data availability is cached, and only until the flag is set.
+        self._cached_data_warning_lock = threading.Lock()
+        self._eval_cached_data_warned = False
+        self._all_flags_cached_data_warned = False
+
         self.__start_up(start_wait)
 
     def postfork(self, start_wait: float = 5):
@@ -411,7 +417,11 @@ def _evaluate_internal(self, key: str, context: Context, default: Any, event_fac
         availability = self._data_system.data_availability
         if availability != DataAvailability.REFRESHED:
             if availability == DataAvailability.CACHED:
-                log.warning("Feature Flag evaluation attempted before client has initialized - using last known values from feature store for feature key: " + key)
+                if not self._eval_cached_data_warned:
+                    with self._cached_data_warning_lock:
+                        if not self._eval_cached_data_warned:
+                            self._eval_cached_data_warned = True
+                            log.warning("Feature Flag evaluation attempted before client has initialized - using last known values from feature store for feature key: " + key + ". This message is logged once.")
             else:
                 log.warning("Feature Flag evaluation attempted before client has initialized! Feature store unavailable - returning default: " + str(default) + " for feature key: " + key)
                 reason = error_reason('CLIENT_NOT_READY')
@@ -483,7 +493,11 @@ def all_flags_state(self, context: Context, **kwargs) -> FeatureFlagsState:
         availability = self._data_system.data_availability
         if availability != DataAvailability.REFRESHED:
             if availability == DataAvailability.CACHED:
-                log.warning("all_flags_state() called before client has finished initializing! Using last known values from feature store")
+                if not self._all_flags_cached_data_warned:
+                    with self._cached_data_warning_lock:
+                        if not self._all_flags_cached_data_warned:
+                            self._all_flags_cached_data_warned = True
+                            log.warning("all_flags_state() called before client has finished initializing! Using last known values from feature store. This message is logged once.")
             else:
                 log.warning("all_flags_state() called before client has finished initializing! Feature store unavailable - returning empty state")
                 return FeatureFlagsState(False)

ldclient/testing/test_async_client.py

@@ -3,6 +3,7 @@
 """
 
 import asyncio
+import logging
 from unittest.mock import AsyncMock, MagicMock, patch
 
 import pytest
@@ -500,3 +501,40 @@ async def fake_evaluate(flag, context, event_factory):
     assert flags_state['flag-good'].get('prerequisites') == ['prereq-x']
     assert 'prerequisites' not in flags_state['flag-bad-last']
     assert 'prerequisites' not in flags_state['flag-bad-first']
+
+
+class UninitializedAsyncUpdateProcessor(MockAsyncUpdateProcessor):
+    def initialized(self) -> bool:
+        return False
+
+
+@pytest.mark.asyncio
+async def test_cached_data_warnings_are_logged_once_per_client(caplog):
+    caplog.set_level(logging.WARNING, logger='ldclient.util')
+    store = MockAsyncFeatureStore()
+    await store.force_set(FEATURES, _make_flag('my-flag', 'hello'))
+    store._initialized = True
+    config = AsyncConfig(
+        "test-sdk-key",
+        feature_store=store,
+        update_processor_class=UninitializedAsyncUpdateProcessor,
+        send_events=False,
+    )
+    client = AsyncLDClient(config)
+    await client.start(start_wait=1.0)
+    context = Context.create('user-1')
+
+    assert await client.variation('my-flag', context, 'default') == 'hello'
+    assert await client.variation('my-flag', context, 'default') == 'hello'
+    assert (await client.all_flags_state(context)).valid
+    assert (await client.all_flags_state(context)).valid
+
+    warnings = [r.message for r in caplog.records if r.levelname == 'WARNING']
+    eval_warnings = [m for m in warnings if m.startswith('Feature Flag evaluation attempted')]
+    all_flags_warnings = [m for m in warnings if m.startswith('all_flags_state() called before')]
+    assert len(eval_warnings) == 1
+    assert len(all_flags_warnings) == 1
+    assert eval_warnings[0].endswith('This message is logged once.')
+    assert all_flags_warnings[0].endswith('This message is logged once.')
+
+    await client.close()

ldclient/testing/test_ldclient_evaluation.py

@@ -1,3 +1,4 @@
+import logging
 import time
 
 from ldclient.client import Config, Context, LDClient
@@ -10,7 +11,7 @@
 from ldclient.testing.builders import *
 from ldclient.testing.mock_components import MockBigSegmentStore
 from ldclient.testing.stub_util import MockEventProcessor, MockUpdateProcessor
-from ldclient.testing.test_ldclient import make_client, user
+from ldclient.testing.test_ldclient import make_client, unreachable_uri, user
 from ldclient.versioned_data_kind import FEATURES, SEGMENTS
 
 flag1 = {'key': 'key1', 'version': 100, 'on': False, 'offVariation': 0, 'variations': ['value1'], 'trackEvents': False}
@@ -425,3 +426,42 @@ def fake_evaluate(flag, context, event_factory):
     assert metadata['good'].get('prerequisites') == ['prereq-of-good']
     assert 'prerequisites' not in metadata['bad-first']
     assert 'prerequisites' not in metadata['bad-last']
+
+
+class UninitializedUpdateProcessor(MockUpdateProcessor):
+    def initialized(self):
+        return False
+
+
+def make_client_with_cached_data(store):
+    return LDClient(
+        config=Config(
+            sdk_key='SDK_KEY',
+            base_uri=unreachable_uri,
+            events_uri=unreachable_uri,
+            stream_uri=unreachable_uri,
+            event_processor_class=MockEventProcessor,
+            update_processor_class=UninitializedUpdateProcessor,
+            feature_store=store,
+        )
+    )
+
+
+def test_cached_data_warnings_are_logged_once_per_client(caplog):
+    caplog.set_level(logging.WARNING, logger='ldclient.util')
+    store = InMemoryFeatureStore()
+    store.init({FEATURES: {'key1': flag1}})
+    client = make_client_with_cached_data(store)
+
+    assert client.variation('key1', user, default='default') == 'value1'
+    assert client.variation('key1', user, default='default') == 'value1'
+    assert client.all_flags_state(user).valid
+    assert client.all_flags_state(user).valid
+
+    warnings = get_log_lines(caplog, 'WARNING')
+    eval_warnings = [m for m in warnings if m.startswith('Feature Flag evaluation attempted')]
+    all_flags_warnings = [m for m in warnings if m.startswith('all_flags_state() called before')]
+    assert len(eval_warnings) == 1
+    assert len(all_flags_warnings) == 1
+    assert eval_warnings[0].endswith('This message is logged once.')
+    assert all_flags_warnings[0].endswith('This message is logged once.')