FFM-7363 Standardise Lifecycle messages (#72)

* FFM-7363 Add SDK codes functionality

* FFM-7363 Add SDK codes test

* FFM-7363 Add SDK codes test

* FFM-7363 Add SDK codes test

* FFM-7363 Add SDK codes test

* FFM-7363 Call logger

* FFM-7363 Update retry message

* FFM-7363 Implement auth messages

* FFM-7363 Implement polling messages

* FFM-7363 Implement streaming messages

* FFM-7363 Implement metrics messages

* FFM-7363 Implement stop messages

* FFM-7363 Implement eval success

* FFM-7363 comment

* FFM-7363 Call init code from polling

* FFM-7363 Tweak init code, and make missing or empty API key exception

* FFM-7363 Fix code

* FFM-7363 Fix code

* FFM-7363 Fix code

* FFM-7363 1.1.15 Release prep

* FFM-7363 Linting

* FFM-7363 Remove unused call

* FFM-7363 Log whole target

* FFM-7363 Add close codes

* FFM-7363 Remove unused call

* FFM-7363 Fix edge case bug with closing sdk if a stream event has ocurred, plus add metrics stop messages

* FFM-7363 Fix edge case bug with closing sdk if a stream event has ocurred, plus add metrics stop messages

* FFM-7363 Lint

Author: erdirowlands

featureflags/__init__.py

@@ -2,4 +2,4 @@
 
 __author__ = """Enver Bisevac"""
 __email__ = "enver.bisevac@harness.io"
-__version__ = '1.1.14'
+__version__ = '1.1.15'

featureflags/analytics.py

@@ -18,6 +18,8 @@
 from .models.metrics_data import MetricsData
 from .models.target_data import TargetData
 from .models.unset import Unset
+from .sdk_logging_codes import info_metrics_thread_started, \
+    info_metrics_success, warn_post_metrics_failed, info_metrics_thread_existed
 from .util import log
 
 FF_METRIC_TYPE = 'FFMETRICS'
@@ -118,8 +120,8 @@ def get_target_key(self, event: AnalyticsEvent) -> str:
 
     def _sync(self) -> None:
         if not self._running:
-            log.info("Starting AnalyticsService with request interval: %d",
-                     self._config.events_sync_interval)
+            info_metrics_thread_started(
+                f'{self._config.events_sync_interval}s')
             self._running = True
             while self._running:
                 time.sleep(self._config.events_sync_interval)
@@ -179,18 +181,16 @@ def _send_data(self) -> None:
                                 environment=self._environment, json_body=body)
         log.debug('Metrics server returns: %d', response.status_code)
         if response.status_code >= 400:
-            log.error(
-                'Error while sending metrics data with status code: %d',
-                response.status_code
-            )
+            warn_post_metrics_failed(response.status_code)
             return
-        log.info('Metrics data sent to server')
+        info_metrics_success()
         return
 
     def close(self) -> None:
         self._running = False
         if len(self._data) > 0:
             self._send_data()
+        info_metrics_thread_existed()
 
     def __enter__(self):
         return self

featureflags/api/default/authenticate.py

@@ -1,4 +1,6 @@
 from typing import Any, Dict, Optional, Union
+
+from featureflags.sdk_logging_codes import warn_auth_retying
 from featureflags.util import log
 
 import httpx
@@ -77,7 +79,7 @@ def handle_http_result(response):
         return True
     else:
         log.error(
-            f'SDK_AUTH_2001: Authentication failed with HTTP code #{code} and '
+            f'Authentication received HTTP code #{code} and '
             'will not attempt to reconnect')
         return False
 
@@ -89,10 +91,9 @@ def _post_request(kwargs, max_auth_retries):
             retry_if_result(lambda response: response.status_code != 200),
             retry_if_result(handle_http_result)
         ),
-        before_sleep=lambda retry_state: log.warning(
-            f'SDK_AUTH_2002: Authentication attempt #'
-            f'{retry_state.attempt_number} '
-            f'got {retry_state.outcome.result()} Retrying...'),
+        before_sleep=lambda retry_state: warn_auth_retying(
+            retry_state.attempt_number,
+            retry_state.retry_state.outcome.result()),
         stop=stop_after_attempt(max_auth_retries),
     )
     return retryer(httpx.post, **kwargs)

featureflags/client.py

@@ -18,11 +18,15 @@
 from .evaluations.auth_target import Target
 from .polling import PollingProcessor
 from .streaming import StreamProcessor
-from .util import log
+import featureflags.sdk_logging_codes as sdk_codes
 
 VERSION: str = "1.0"
 
 
+class MissingOrEmptyAPIKeyException(Exception):
+    pass
+
+
 class CfClient(object):
     def __init__(
             self, sdk_key: str,
@@ -33,6 +37,9 @@ def __init__(
         #  The Client is considered initialized when flags and groups
         #  are loaded into cache.
         self._initialized = threading.Event()
+        # Keep track if initialization has failed due to authentication
+        # or a missing/empty API key.
+        self._initialized_failed = False
         self._auth_token: Optional[str] = None
         self._environment_id: Optional[str] = None
         self._sdk_key: Optional[str] = sdk_key
@@ -56,7 +63,10 @@ def __init__(
 
     def run(self):
         try:
+            if self._sdk_key is None or self._sdk_key == "":
+                raise MissingOrEmptyAPIKeyException()
             self.authenticate()
+            sdk_codes.info_sdk_auth_ok()
             streaming_event = threading.Event()
             polling_event = threading.Event()
 
@@ -97,24 +107,31 @@ def run(self):
                 )
 
         except RetryError:
-            log.error(
-                "Authentication failed and max retries have been exceeded - "
-                "defaults will be served.")
-            # Mark the client as initialized in case wait_for_initialization
-            # is called. The SDK has already logged that authentication
-            # failed and defaults will be returned.
+            sdk_codes.warn_auth_failed_exceed_retries()
+            sdk_codes.warn_failed_init_auth_error()
+            self._initialized_failed = True
+            # We just need to unblock the thread here
+            # in case wait_for_intialization was called. The SDK has already
+            # logged that authentication failed and defaults will be returned.
             self._initialized.set()
         except UnrecoverableAuthenticationException:
-            log.error(
-                "Authentication failed - defaults will be served.")
-            # Same again, just mark the client as initailized.
+            self._initialized_failed = True
+            sdk_codes.warn_auth_failed_srv_defaults()
+            sdk_codes.warn_failed_init_auth_error()
+            # Same again, unblock the thread.
+            self._initialized.set()
+        except MissingOrEmptyAPIKeyException:
+            self._initialized_failed = True
+            sdk_codes.wan_missing_sdk_key()
+            # And again, unblock the thread.
             self._initialized.set()
 
     def wait_for_initialization(self):
-        log.debug("Waiting for initialization to finish")
         self._initialized.wait()
 
     def is_initialized(self):
+        if self._initialized_failed:
+            return False
         return self._initialized.is_set()
 
     def get_environment_id(self):
@@ -211,14 +228,14 @@ def json_variation(self, identifier: str, target: Target,
         return variation.json(target, identifier, default)
 
     def close(self):
-        log.info('closing sdk client')
+        sdk_codes.info_sdk_start_close()
         self._polling_processor.stop()
         if self._config.enable_stream:
             self._stream.stop()
 
         if self._config.enable_analytics:
             self._analytics.close()
-        log.info('All threads finished')
+        sdk_codes.info_sdk_close_success()
 
     def __enter__(self):
         return self

featureflags/evaluations/variation.py

@@ -22,51 +22,76 @@ class Variation(object):
     def bool(self, target: Target, flag_identifier: str,
              default: bool = False) -> bool:
         if self.value:
-            return self.value.lower() == "true"
+            result = self.value.lower() == "true"
+            log.info(
+                "SDKCODE:6000: Evaluated bool variation successfully:"
+                "%s", {"result": result, "flag identifier": flag_identifier,
+                       "target": target})
+            return result
         log.error(
-            "SDK_EVAL_6001: Failed to evaluate bool variation for %s and the "
+            "SDKCODE:6001: Failed to evaluate bool variation for %s and the "
             "default variation '%s' is being returned",
-            {"target": target.identifier, "flag": flag_identifier}, default)
+            {"target": target, "flag": flag_identifier}, default)
         return default
 
     def string(self, target: Target, flag_identifier: str,
                default: str) -> str:
         if self.value:
-            return self.value
+            result = self.value
+            log.info(
+                "SDKCODE:6000: Evaluated string variation successfully:"
+                "%s", {"result": result, "flag identifier": flag_identifier,
+                       "target": target})
+            return result
         log.error(
-            "SDK_EVAL_6001: Failed to evaluate string variation for %s and the"
+            "SDKCODE:6001: Failed to evaluate string variation for %s and the"
             " default variation '%s' is being returned",
-            {"target": target.identifier, "flag": flag_identifier}, default)
+            {"target": target, "flag": flag_identifier}, default)
         return default
 
     def number(self, target: Target, flag_identifier: str,
                default: float) -> float:
         if self.value:
-            return float(self.value)
+            result = float(self.value)
+            log.info(
+                "SDKCODE:6000: Evaluated number variation successfully:"
+                "%s", {"result": result, "flag identifier": flag_identifier,
+                       "target": target})
+            return result
         log.error(
-            "SDK_EVAL_6001: Failed to evaluate number variation for %s and the"
+            "SDKCODE:6001: Failed to evaluate number variation for %s and the"
             " default variation '%s' is being returned",
-            {"target": target.identifier, "flag": flag_identifier}, default)
+            {"target": target, "flag": flag_identifier}, default)
         return default
 
     def int(self, target: Target, flag_identifier: str,
             default: int) -> int:
         if self.value:
-            return int(self.value)
+            result = int(self.value)
+            log.info(
+                "SDKCODE:6000: Evaluated number variation successfully:"
+                "%s", {"result": result, "flag identifier": flag_identifier,
+                       "target": target})
+            return result
         log.error(
-            "SDK_EVAL_6001: Failed to evaluate int variation for %s and the "
+            "SDKCODE:6001: Failed to evaluate int variation for %s and the "
             "default variation '%s' is being returned",
-            {"target": target.identifier, "flag": flag_identifier}, default)
+            {"target": target, "flag": flag_identifier}, default)
         return default
 
     def json(self, target: Target, flag_identifier: str,
              default: dict) -> dict:
         if self.value:
-            return json.loads(self.value)
+            result = json.loads(self.value)
+            log.info(
+                "SDKCODE:6000: Evaluated json variation successfully:"
+                "%s", {"result": result, "flag identifier": flag_identifier,
+                       "target": target})
+            return result
         log.error(
-            "SDK_EVAL_6001: Failed to evaluate json variation for %s and the "
+            "SDKCODE:6001: Failed to evaluate json variation for %s and the "
             "default variation '%s' is being returned",
-            {"target": target.identifier, "flag": flag_identifier}, default)
+            {"target": target, "flag": flag_identifier}, default)
         return default
 
     def to_dict(self) -> Dict[str, Any]:

featureflags/polling.py

@@ -7,6 +7,8 @@
 from .api.default.get_all_segments import sync as retrieve_segments
 from .api.default.get_feature_config import sync as retrieve_flags
 from .config import Config
+from .sdk_logging_codes import info_poll_started, info_polling_stopped, \
+    info_sdk_init_ok, info_sdk_init_waiting
 from .util import log
 
 
@@ -39,6 +41,7 @@ def run(self):
             self.__running = True
             #  Get initial flags and groups
             try:
+                info_sdk_init_waiting()
                 log.info("Fetching initial target segments and flags")
                 self.retrieve_flags_and_segments()
                 log.info("Initial target segments and flags fetched. "
@@ -47,7 +50,7 @@ def run(self):
                 #  Segments and flags have been cached so
                 #  mark the Client as initialised.
                 self.__wait_for_initialization.set()
-                log.debug("CfClient initialized")
+                info_sdk_init_ok()
             except Exception as ex:
                 log.exception(
                     'Error: Exception encountered when '
@@ -56,15 +59,13 @@ def run(self):
                 )
             #  Sleep for an interval before going into the polling loop.
             time.sleep(self.__config.pull_interval)
-            log.info("Starting PollingProcessor with request interval: " +
-                     str(self.__config.pull_interval))
+            info_poll_started(self.__config.pull_interval)
             while self.__running:
                 start_time = time.time()
                 try:
                     if self.__config.enable_stream and \
                             self.__stream_ready.is_set():
-                        log.debug('Poller will be paused because' +
-                                  ' streaming mode is active')
+                        info_polling_stopped('streaming mode is active')
                         # on stream disconnect, make sure flags are in sync
                         self.retrieve_flags_and_segments()
                         #  Block until ready.set() is called
@@ -87,8 +88,9 @@ def run(self):
                     time.sleep(self.__config.pull_interval - elapsed)
 
     def stop(self):
-        log.info("Stopping PollingProcessor")
         self.__running = False
+        info_polling_stopped("Client was closed")
+
 
     def retrieve_flags_and_segments(self):
         t1 = Thread(target=self.__retrieve_segments)