diff --git a/lms/djangoapps/email_marketing/signals.py b/lms/djangoapps/email_marketing/signals.py index e158bf6f753548a57314e49f53339c54e2b81039..a8723ea92dd1902f66c94f2e71b18e969271ade3 100644 --- a/lms/djangoapps/email_marketing/signals.py +++ b/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) diff --git a/lms/djangoapps/email_marketing/tests/test_signals.py b/lms/djangoapps/email_marketing/tests/test_signals.py index b2fceb95b05ccb97ac64f6f2899804dcfe2e442a..764fbc9c7911d0e3f68c2ce34e7656e8cd11fddb 100644 --- a/lms/djangoapps/email_marketing/tests/test_signals.py +++ b/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'},