added lots of debug logging to trace errors with taar service

setup.py

@@ -3,7 +3,7 @@ from setuptools import find_packages, setup
 setup(
     name='mozilla-taar3',
     use_scm_version=False,
-    version='0.3.1',
+    version='0.3.2',
     setup_requires=['setuptools_scm', 'pytest-runner'],
     tests_require=['pytest'],
     include_package_data = True,

taar/profile_fetcher.py

@@ -39,10 +39,11 @@ class ProfileController:
             json_byte_data = zlib.decompress(compressed_bytes)
             json_str_data = json_byte_data.decode('utf8')
             return json.loads(json_str_data)
-        except Exception:
+        except Exception as e:
             # Return None on error.  The caller in ProfileFetcher will
             # handle error logging
-            self.logger.error("Error loading client data for [%s]" % client_id)
+            msg = "Error loading client data for {}.  Error: {}"
+            self.logger.error(msg.format(client_id, str(e)))
             return None
 
 

taar/recommenders/ensemble_recommender.py

@@ -37,7 +37,7 @@ class EnsembleRecommender(AbstractRecommender):
     def __init__(self, ctx):
         self.RECOMMENDER_KEYS = ['collaborative', 'similarity', 'locale']
         self._ctx = ctx
-        self.logger = self._ctx[IMozLogging].get_logger('taar')
+        self.logger = self._ctx[IMozLogging].get_logger('taar.ensemble')
 
         assert 'recommender_factory' in self._ctx
 
@@ -56,8 +56,10 @@ class EnsembleRecommender(AbstractRecommender):
     def can_recommend(self, client_data, extra_data={}):
         """The ensemble recommender is always going to be
         available if at least one recommender is available"""
-        return sum([self._recommender_map[rkey].can_recommend(client_data)
-                    for rkey in self.RECOMMENDER_KEYS])
+        result = sum([self._recommender_map[rkey].can_recommend(client_data)
+                      for rkey in self.RECOMMENDER_KEYS])
+        self.logger.info("Ensemble can_recommend: {}".format(result))
+        return result
 
     def recommend(self, client_data, limit, extra_data={}):
         """
@@ -73,7 +75,7 @@ class EnsembleRecommender(AbstractRecommender):
         weight each recommender appropriate so that the ordering is
         correct.
         """
-
+        self.logger.info("Ensemble recommend invoked")
         preinstalled_addon_ids = client_data.get('installed_addons', [])
 
         # Compute an extended limit by adding the length of

taar/recommenders/hybrid_recommender.py

@@ -57,12 +57,13 @@ class CuratedRecommender(AbstractRecommender):
     def __init__(self, ctx):
         self._ctx = ctx
 
-        self.logger = self._ctx[IMozLogging].get_logger('taar')
+        self.logger = self._ctx[IMozLogging].get_logger('taar.curated')
         self._curated_wl = CuratedWhitelistCache(self._ctx)
 
     def can_recommend(self, client_data, extra_data={}):
         """The Curated recommender will always be able to recommend
         something"""
+        self.logger.info("Curated can_recommend: {}".format(True))
         return True
 
     def recommend(self, client_data, limit, extra_data={}):
@@ -71,10 +72,10 @@ class CuratedRecommender(AbstractRecommender):
         """
         guids = self._curated_wl.get_randomized_guid_sample(limit)
 
-        log_data = (client_data['client_id'], str(guids))
-        self.logger.info("client_id: [%s], guids: [%s]" % log_data)
-
         results = [(guid, 1.0) for guid in guids]
+
+        log_data = (client_data['client_id'], str(guids))
+        self.logger.info("Curated recommendations client_id: [%s], guids: [%s]" % log_data)
         return results
 
 
@@ -98,7 +99,9 @@ class HybridRecommender(AbstractRecommender):
         available if at least one recommender is available"""
         ensemble_recommend = self._ensemble_recommender.can_recommend(client_data, extra_data)
         curated_recommend = self._curated_recommender.can_recommend(client_data, extra_data)
-        return ensemble_recommend and curated_recommend
+        result = ensemble_recommend and curated_recommend
+        self.logger.info("Hybrid can_recommend: {}".format(result))
+        return result
 
     def recommend(self, client_data, limit, extra_data={}):
         """
@@ -145,7 +148,7 @@ class HybridRecommender(AbstractRecommender):
                 merged_results.add(r2)
 
         if len(merged_results) < limit:
-            msg = "Insufficient recommendations found for client: %s" % client_data['client_id']
+            msg = "Defaulting to empty results. Insufficient recommendations found for client: %s" % client_data['client_id']
             self.logger.info(msg)
             return []
 
@@ -156,5 +159,5 @@ class HybridRecommender(AbstractRecommender):
         log_data = (client_data['client_id'],
                     str([r[0] for r in sorted_results]))
 
-        self.logger.info("client_id: [%s], guids: [%s]" % log_data)
+        self.logger.info("Hybrid recommendations client_id: [%s], guids: [%s]" % log_data)
         return sorted_results

taar/recommenders/lazys3.py

@@ -67,8 +67,8 @@ class LazyJSONLoader:
                     .get()['Body']
                     .read()
                 )
-                msg = "Loaded JSON from S3: {}".format(self._key_str)
-                self.logger.info(msg)
+                msg = "Loaded JSON from S3: {}. Byte count: {}"
+                self.logger.info(msg.format(self._key_str, len(raw_bytes)))
 
                 raw_data = (
                     raw_bytes.decode('utf-8')

taar/recommenders/recommendation_manager.py

@@ -17,8 +17,11 @@ from taar.schema import INTERVENTION_A
 from taar.schema import INTERVENTION_B
 from taar.schema import INTERVENTION_CONTROL
 
-logger = logging.getLogger(__name__)
+from taar.context import default_context
+from srgutil.interfaces import IMozLogging
 
+ctx = default_context()
+schema_logger = ctx[IMozLogging].get_logger('taar.schema_validate')
 
 def schema_validate(colandar_schema):
     """
@@ -63,11 +66,11 @@ def schema_validate(colandar_schema):
             try:
                 schema.deserialize(json_args)
             except colander.Invalid as e:
-                msg = "Error deserializing input arguments: " + str(e.asdict().values())
+                msg = "Defaulting to empty results. Error deserializing input arguments: " + str(e.asdict().values())
 
                 # This logger can't use the context logger as the code
                 # is running in a method decorator
-                logger.warn(msg)
+                schema_logger.warn(msg)
                 # Invalid data means TAAR safely returns an empty list
                 return []
             return func(*w_args, **w_kwargs)
@@ -133,6 +136,7 @@ class RecommendationManager:
         """
         client_info = self.profile_fetcher.get(client_id)
         if client_info is None:
+            self.logger.warn("Defaulting to empty results.  No client info fetched from dynamo.")
             return []
 
         # Select recommendation output based on extra_data['branch']
@@ -144,15 +148,18 @@ class RecommendationManager:
 
     def recommend_intervention_a(self, client_info, client_id, limit, extra_data):
         """ Intervention A is the ensemble method """
+        self.logger.info("Intervention A recommendation method invoked")
         recommender = self._recommender_map[INTERVENTION_A]
         return recommender.recommend(client_info, limit, extra_data)
 
     def recommend_intervention_b(self, client_info, client_id, limit, extra_data):
         """ Intervention A is the ensemble method hybridized with a
         curated list of addons """
+        self.logger.info("Intervention B recommendation method invoked")
         recommender = self._recommender_map[INTERVENTION_B]
         return recommender.recommend(client_info, limit, extra_data)
 
-    def recommend_intervention_control(self, client_info, client_id, limit, extra_data):
+    def recommend_control(self, client_info, client_id, limit, extra_data):
         """Run the control recommender - that is nothing"""
+        self.logger.info("Control recommendation method invoked")
         return []

tests/test_recommendation_manager.py

@@ -10,6 +10,7 @@ from taar.recommenders import RecommendationManager
 from taar.recommenders.lazys3 import LazyJSONLoader
 from taar.schema import INTERVENTION_A
 from taar.schema import INTERVENTION_B
+from taar.schema import INTERVENTION_CONTROL
 from taar.recommenders.base_recommender import AbstractRecommender
 from .mocks import MockProfileController, MockRecommenderFactory
 from .test_hybrid_recommender import install_mock_curated_data
@@ -63,33 +64,7 @@ def test_none_profile_returns_empty_list(test_ctx):
 
 
 @mock_s3
-def test_intervention_b(test_ctx):
-    """The recommendation manager is currently very naive and just
-    selects the first recommender which returns 'True' to
-    can_recommend()."""
-
-    ctx = install_mocks(test_ctx)
-    ctx = install_mock_curated_data(ctx)
-
-    factory = MockRecommenderFactory()
-
-    class MockProfileFetcher:
-        def get(self, client_id):
-            return {'client_id': client_id}
-
-    ctx['recommender_factory'] = factory
-    ctx['profile_fetcher'] = MockProfileFetcher()
-    manager = RecommendationManager(ctx.child())
-    recommendation_list = manager.recommend('some_ignored_id',
-                                            4,
-                                            extra_data={'branch': INTERVENTION_B})
-
-    assert isinstance(recommendation_list, list)
-    assert len(recommendation_list) == 4
-
-
-@mock_s3
-def test_recommendations_via_manager(test_ctx):
+def test_intervention_a(test_ctx):
     ctx = install_mocks(test_ctx)
 
     EXPECTED_RESULTS = [('ghi', 3430.0),
@@ -118,3 +93,60 @@ def test_recommendations_via_manager(test_ctx):
 
     assert isinstance(recommendation_list, list)
     assert recommendation_list == EXPECTED_RESULTS
+
+
+@mock_s3
+def test_intervention_b(test_ctx):
+    """The recommendation manager is currently very naive and just
+    selects the first recommender which returns 'True' to
+    can_recommend()."""
+
+    ctx = install_mocks(test_ctx)
+    ctx = install_mock_curated_data(ctx)
+
+    factory = MockRecommenderFactory()
+
+    class MockProfileFetcher:
+        def get(self, client_id):
+            return {'client_id': client_id}
+
+    ctx['recommender_factory'] = factory
+    ctx['profile_fetcher'] = MockProfileFetcher()
+    manager = RecommendationManager(ctx.child())
+    recommendation_list = manager.recommend('some_ignored_id',
+                                            4,
+                                            extra_data={'branch': INTERVENTION_B})
+
+    assert isinstance(recommendation_list, list)
+    assert len(recommendation_list) == 4
+
+
+@mock_s3
+def test_intervention_control(test_ctx):
+    ctx = install_mocks(test_ctx)
+    ctx = install_mock_curated_data(ctx)
+
+    factory = MockRecommenderFactory()
+
+    class MockProfileFetcher:
+        def get(self, client_id):
+            return {'client_id': client_id}
+
+    ctx['recommender_factory'] = factory
+    ctx['profile_fetcher'] = MockProfileFetcher()
+    manager = RecommendationManager(ctx.child())
+    recommendation_list = manager.recommend('some_ignored_id',
+                                            10,
+                                            extra_data={'branch': INTERVENTION_CONTROL})
+
+    assert len(recommendation_list) == 0
+
+
+def test_fixed_client_id_valid():
+    # return 4 arbitrary GUIDs from the shortlist
+    pass
+
+def test_fixed_client_id_empty_list():
+    # return an empty list
+    pass
+