Overhaul logging integration. (#123)

* Overhaul logging integration.
* Update README to reflect more modern install conventions.
* Refactor SimpleLogger/NoOpLogger to use standard python logging.
* Update tests.
* Fix logger deprecation warning test.

Author: amilstead

.gitignore

@@ -9,12 +9,16 @@ MANIFEST
 dist
 
 # Output of running coverage locally
+cover
 .coverage
 
 # From python-testapp.git
 .idea/
 .virt/
 datafile.json
 
+# vim swap files
+*.swp
+
 # OSX folder metadata
 *.DS_Store

README.md

@@ -26,23 +26,20 @@ See the Optimizely Full Stack [developer documentation](http://developers.optimi
 
 ### Building the SDK
 
-Build the SDK using the following command:
+Build and install the SDK with pip, using the following command:
 
 ```
-python setup.py sdist
+pip install -e .
 ```
 
-This will create a tarball under `dist/`
+### Unit tests
 
-You can then install the SDK and its dependencies with:
+##### Running all tests
 
+To get test dependencies installed, use a modified version of the install command:
 ```
-pip install dist/optimizely-sdk-{VERSION}.tar.gz
+pip install -e .[test]
 ```
-
-### Unit tests
-
-##### Running all tests
 You can run all unit tests with:
 
 ```

optimizely/bucketer.py

@@ -80,9 +80,10 @@ def find_bucket(self, bucketing_id, parent_id, traffic_allocations):
 
     bucketing_key = BUCKETING_ID_TEMPLATE.format(bucketing_id=bucketing_id, parent_id=parent_id)
     bucketing_number = self._generate_bucket_value(bucketing_key)
-    self.config.logger.log(enums.LogLevels.DEBUG,
-                           'Assigned bucket %s to user with bucketing ID "%s".' % (bucketing_number,
-                                                                                   bucketing_id))
+    self.config.logger.debug('Assigned bucket %s to user with bucketing ID "%s".' % (
+      bucketing_number,
+      bucketing_id
+    ))
 
     for traffic_allocation in traffic_allocations:
       current_end_of_range = traffic_allocation.get('endOfRange')
@@ -115,24 +116,33 @@ def bucket(self, experiment, user_id, bucketing_id):
 
       user_experiment_id = self.find_bucket(bucketing_id, experiment.groupId, group.trafficAllocation)
       if not user_experiment_id:
-        self.config.logger.log(enums.LogLevels.INFO, 'User "%s" is in no experiment.' % user_id)
+        self.config.logger.info('User "%s" is in no experiment.' % user_id)
         return None
 
       if user_experiment_id != experiment.id:
-        self.config.logger.log(enums.LogLevels.INFO, 'User "%s" is not in experiment "%s" of group %s.' %
-                               (user_id, experiment.key, experiment.groupId))
+        self.config.logger.info('User "%s" is not in experiment "%s" of group %s.' % (
+          user_id,
+          experiment.key,
+          experiment.groupId
+        ))
         return None
 
-      self.config.logger.log(enums.LogLevels.INFO, 'User "%s" is in experiment %s of group %s.' %
-                             (user_id, experiment.key, experiment.groupId))
+      self.config.logger.info('User "%s" is in experiment %s of group %s.' % (
+        user_id,
+        experiment.key,
+        experiment.groupId
+      ))
 
     # Bucket user if not in white-list and in group (if any)
     variation_id = self.find_bucket(bucketing_id, experiment.id, experiment.trafficAllocation)
     if variation_id:
       variation = self.config.get_variation_from_id(experiment.key, variation_id)
-      self.config.logger.log(enums.LogLevels.INFO, 'User "%s" is in variation "%s" of experiment %s.' %
-                             (user_id, variation.key, experiment.key))
+      self.config.logger.info('User "%s" is in variation "%s" of experiment %s.' % (
+        user_id,
+        variation.key,
+        experiment.key
+      ))
       return variation
 
-    self.config.logger.log(enums.LogLevels.INFO, 'User "%s" is in no variation.' % user_id)
+    self.config.logger.info('User "%s" is in no variation.' % user_id)
     return None

optimizely/decision_service.py

@@ -11,7 +11,6 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-import sys
 from collections import namedtuple
 
 from . import bucketer
@@ -21,7 +20,6 @@
 from .helpers import validator
 from .user_profile import UserProfile
 
-
 Decision = namedtuple('Decision', 'experiment variation source')
 DECISION_SOURCE_EXPERIMENT = 'experiment'
 DECISION_SOURCE_ROLLOUT = 'rollout'
@@ -68,8 +66,7 @@ def get_forced_variation(self, experiment, user_id):
       variation_key = forced_variations.get(user_id)
       variation = self.config.get_variation_from_key(experiment.key, variation_key)
       if variation:
-        self.config.logger.log(enums.LogLevels.INFO,
-                               'User "%s" is forced in variation "%s".' % (user_id, variation_key))
+        self.logger.info('User "%s" is forced in variation "%s".' % (user_id, variation_key))
       return variation
 
     return None
@@ -91,9 +88,11 @@ def get_stored_variation(self, experiment, user_profile):
     if variation_id:
       variation = self.config.get_variation_from_id(experiment.key, variation_id)
       if variation:
-        self.config.logger.log(enums.LogLevels.INFO,
-                               'Found a stored decision. User "%s" is in variation "%s" of experiment "%s".' %
-                               (user_id, variation.key, experiment.key))
+        self.logger.info('Found a stored decision. User "%s" is in variation "%s" of experiment "%s".' % (
+          user_id,
+          variation.key,
+          experiment.key
+        ))
         return variation
 
     return None
@@ -119,7 +118,7 @@ def get_variation(self, experiment, user_id, attributes, ignore_user_profile=Fal
 
     # Check if experiment is running
     if not experiment_helper.is_experiment_running(experiment):
-      self.logger.log(enums.LogLevels.INFO, 'Experiment "%s" is not running.' % experiment.key)
+      self.logger.info('Experiment "%s" is not running.' % experiment.key)
       return None
 
     # Check if the user is forced into a variation
@@ -138,11 +137,7 @@ def get_variation(self, experiment, user_id, attributes, ignore_user_profile=Fal
       try:
         retrieved_profile = self.user_profile_service.lookup(user_id)
       except:
-        error = sys.exc_info()[1]
-        self.logger.log(
-          enums.LogLevels.ERROR,
-          'Unable to retrieve user profile for user "%s" as lookup failed. Error: %s' % (user_id, str(error))
-        )
+        self.logger.exception('Unable to retrieve user profile for user "%s" as lookup failed.' % user_id)
         retrieved_profile = None
 
       if validator.is_user_profile_valid(retrieved_profile):
@@ -151,14 +146,14 @@ def get_variation(self, experiment, user_id, attributes, ignore_user_profile=Fal
         if variation:
           return variation
       else:
-        self.logger.log(enums.LogLevels.WARNING, 'User profile has invalid format.')
+        self.logger.warning('User profile has invalid format.')
 
     # Bucket user and store the new decision
     if not audience_helper.is_user_in_experiment(self.config, experiment, attributes):
-      self.logger.log(
-        enums.LogLevels.INFO,
-        'User "%s" does not meet conditions to be in experiment "%s".' % (user_id, experiment.key)
-      )
+      self.logger.info('User "%s" does not meet conditions to be in experiment "%s".' % (
+        user_id,
+        experiment.key
+      ))
       return None
 
     # Determine bucketing ID to be used
@@ -172,9 +167,7 @@ def get_variation(self, experiment, user_id, attributes, ignore_user_profile=Fal
           user_profile.save_variation_for_experiment(experiment.id, variation.id)
           self.user_profile_service.save(user_profile.__dict__)
         except:
-          error = sys.exc_info()[1]
-          self.logger.log(enums.LogLevels.ERROR,
-                          'Unable to save user profile for user "%s". Error: %s' % (user_id, str(error)))
+          self.logger.exception('Unable to save user profile for user "%s".' % user_id)
       return variation
 
     return None
@@ -199,25 +192,27 @@ def get_variation_for_rollout(self, rollout, user_id, attributes=None):
 
         # Check if user meets audience conditions for targeting rule
         if not audience_helper.is_user_in_experiment(self.config, experiment, attributes):
-          self.logger.log(
-            enums.LogLevels.DEBUG,
-            'User "%s" does not meet conditions for targeting rule %s.' % (user_id, idx + 1)
-          )
+          self.logger.debug('User "%s" does not meet conditions for targeting rule %s.' % (
+            user_id,
+            idx + 1
+          ))
           continue
 
-        self.logger.log(enums.LogLevels.DEBUG, 'User "%s" meets conditions for targeting rule %s.' % (user_id, idx + 1))
+        self.logger.debug('User "%s" meets conditions for targeting rule %s.' % (user_id, idx + 1))
         # Determine bucketing ID to be used
         bucketing_id = self._get_bucketing_id(user_id, attributes)
         variation = self.bucketer.bucket(experiment, user_id, bucketing_id)
         if variation:
-          self.logger.log(enums.LogLevels.DEBUG,
-                          'User "%s" is in variation %s of experiment %s.' % (user_id, variation.key, experiment.key))
+          self.logger.debug('User "%s" is in variation %s of experiment %s.' % (
+            user_id,
+            variation.key,
+            experiment.key
+          ))
           return Decision(experiment, variation, DECISION_SOURCE_ROLLOUT)
         else:
           # Evaluate no further rules
-          self.logger.log(enums.LogLevels.DEBUG,
-                          'User "%s" is not in the traffic group for the targeting else. '
-                          'Checking "Everyone Else" rule now.' % user_id)
+          self.logger.debug('User "%s" is not in the traffic group for the targeting else. '
+                            'Checking "Everyone Else" rule now.' % user_id)
           break
 
       # Evaluate last rule i.e. "Everyone Else" rule
@@ -229,8 +224,7 @@ def get_variation_for_rollout(self, rollout, user_id, attributes=None):
         bucketing_id = self._get_bucketing_id(user_id, attributes)
         variation = self.bucketer.bucket(everyone_else_experiment, user_id, bucketing_id)
         if variation:
-          self.logger.log(enums.LogLevels.DEBUG,
-                          'User "%s" meets conditions for targeting rule "Everyone Else".' % user_id)
+          self.logger.debug('User "%s" meets conditions for targeting rule "Everyone Else".' % user_id)
           return Decision(everyone_else_experiment, variation, DECISION_SOURCE_ROLLOUT)
 
     return Decision(None, None, DECISION_SOURCE_ROLLOUT)
@@ -250,14 +244,17 @@ def get_experiment_in_group(self, group, bucketing_id):
     if experiment_id:
       experiment = self.config.get_experiment_from_id(experiment_id)
       if experiment:
-        self.logger.log(enums.LogLevels.INFO,
-                        'User with bucketing ID "%s" is in experiment %s of group %s.' %
-                        (bucketing_id, experiment.key, group.id))
+        self.logger.info('User with bucketing ID "%s" is in experiment %s of group %s.' % (
+          bucketing_id,
+          experiment.key,
+          group.id
+        ))
         return experiment
 
-    self.logger.log(enums.LogLevels.INFO,
-                    'User with bucketing ID "%s" is not in any experiments of group %s.' %
-                    (bucketing_id, group.id))
+    self.logger.info('User with bucketing ID "%s" is not in any experiments of group %s.' % (
+      bucketing_id,
+      group.id
+    ))
 
     return None
 
@@ -286,10 +283,13 @@ def get_variation_for_feature(self, feature, user_id, attributes=None):
           variation = self.get_variation(experiment, user_id, attributes)
 
           if variation:
-            self.logger.log(enums.LogLevels.DEBUG,
-                            'User "%s" is in variation %s of experiment %s.' % (user_id, variation.key, experiment.key))
+            self.logger.debug('User "%s" is in variation %s of experiment %s.' % (
+              user_id,
+              variation.key,
+              experiment.key
+            ))
       else:
-        self.logger.log(enums.LogLevels.ERROR, enums.Errors.INVALID_GROUP_ID_ERROR.format('_get_variation_for_feature'))
+        self.logger.error(enums.Errors.INVALID_GROUP_ID_ERROR.format('_get_variation_for_feature'))
 
     # Next check if the feature is being experimented on
     elif feature.experimentIds:
@@ -299,8 +299,11 @@ def get_variation_for_feature(self, feature, user_id, attributes=None):
         variation = self.get_variation(experiment, user_id, attributes)
 
         if variation:
-          self.logger.log(enums.LogLevels.DEBUG,
-                          'User "%s" is in variation %s of experiment %s.' % (user_id, variation.key, experiment.key))
+          self.logger.debug('User "%s" is in variation %s of experiment %s.' % (
+            user_id,
+            variation.key,
+            experiment.key
+          ))
 
     # Next check if user is part of a rollout
     if not variation and feature.rolloutId: