Logging Sailthru api call time for exploring optimal connection timeout value.

ECOM-7772

lms/djangoapps/email_marketing/signals.py

@@ -64,10 +64,14 @@ def add_email_marketing_cookies(sender, response=None, user=None,
             post_parms.get('cookies', ''),
             user.email
         )
+        time_before_call = datetime.datetime.now()
+
         sailthru_response = \
             sailthru_client.api_post("user", post_parms)
+
     except SailthruClientError as exc:
         log.error("Exception attempting to obtain cookie from Sailthru: %s", unicode(exc))
+
         return response
 
     if sailthru_response.is_ok():
@@ -81,12 +85,14 @@ def add_email_marketing_cookies(sender, response=None, user=None,
                 domain=settings.SESSION_COOKIE_DOMAIN,
                 path='/',
             )
+            _log_sailthru_api_call_time(time_before_call)
         else:
             log.error("No cookie returned attempting to obtain cookie from Sailthru for %s", user.email)
     else:
         error = sailthru_response.get_error()
         # generally invalid email address
         log.info("Error attempting to obtain cookie from Sailthru: %s", error.get_message())
+
     return response
 
 
@@ -191,3 +197,17 @@ def _get_current_site():
         return
 
     return {'id': request.site.id, 'domain': request.site.domain, 'name': request.site.name}
+
+
+def _log_sailthru_api_call_time(time_before_call):
+    """
+    Logs Sailthru api synchronous call time
+    """
+
+    time_after_call = datetime.datetime.now()
+    delta_sailthru_api_call_time = time_after_call - time_before_call
+
+    log.info("Started at %s and ended at %s, time spent:%s milliseconds",
+             time_before_call.isoformat(' '),
+             time_after_call.isoformat(' '),
+             delta_sailthru_api_call_time.microseconds / 1000)

lms/djangoapps/email_marketing/tests/test_signals.py

@@ -8,6 +8,8 @@ from django.contrib.auth.models import AnonymousUser
 from django.contrib.sites.models import Site
 from mock import patch, ANY
 from util.json_request import JsonResponse
+from testfixtures import LogCapture
+from freezegun import freeze_time
 
 from email_marketing.signals import email_marketing_register_user, \
     email_marketing_user_field_changed, \
@@ -27,6 +29,8 @@ from sailthru.sailthru_error import SailthruClientError
 
 log = logging.getLogger(__name__)
 
+LOGGER_NAME = "email_marketing.signals"
+
 TEST_EMAIL = "test@edx.org"
 
 
@@ -77,6 +81,7 @@ class EmailMarketingTests(TestCase):
         self.request.site = self.site
         super(EmailMarketingTests, self).setUp()
 
+    @freeze_time(datetime.datetime.now())
     @patch('email_marketing.signals.crum.get_current_request')
     @patch('email_marketing.signals.SailthruClient.api_post')
     def test_drop_cookie(self, mock_sailthru, mock_get_current_request):
@@ -90,7 +95,20 @@ class EmailMarketingTests(TestCase):
         self.request.COOKIES['anonymous_interest'] = 'cookie_content'
         mock_get_current_request.return_value = self.request
         mock_sailthru.return_value = SailthruResponse(JsonResponse({'keys': {'cookie': 'test_cookie'}}))
-        add_email_marketing_cookies(None, response=response, user=self.user)
+        cookie_log = "Sending to Sailthru the user interest cookie [{'anonymous_interest': 'cookie_content'}]" \
+                     ' for user [test@edx.org]'
+
+        with LogCapture(LOGGER_NAME, level=logging.INFO) as logger:
+            add_email_marketing_cookies(None, response=response, user=self.user)
+            logger.check(
+                (LOGGER_NAME, 'INFO', cookie_log),
+                (LOGGER_NAME, 'INFO',
+                    'Started at {start} and ended at {end}, time spent:{delta} milliseconds'.format(
+                        start=datetime.datetime.now().isoformat(' '),
+                        end=datetime.datetime.now().isoformat(' '),
+                        delta=0)
+                 )
+            )
         mock_sailthru.assert_called_with('user',
                                          {'fields': {'keys': 1},
                                           'cookies': {'anonymous_interest': 'cookie_content'},