Merge pull request #20655 from edx/dsheraz/email-logging

added time logs for bulk email

lms/djangoapps/bulk_email/tasks.py

@@ -7,7 +7,9 @@ import json
 import logging
 import random
 import re
+import time
 from collections import Counter
+from datetime import datetime
 from smtplib import SMTPConnectError, SMTPDataError, SMTPException, SMTPServerDisconnected
 from time import sleep
 
@@ -207,6 +209,10 @@ def perform_delegate_email_batches(entry_id, course_id, task_input, action_name)
     def _create_send_email_subtask(to_list, initial_subtask_status):
         """Creates a subtask to send email to a given recipient list."""
         subtask_id = initial_subtask_status.task_id
+        log.info(
+            u"BulkEmail Task: %s Subtask: %s starting at %s in Queue: %s",
+            task_id, subtask_id, datetime.now(), routing_key
+        )
         new_subtask = send_course_email.subtask(
             (
                 entry_id,
@@ -295,6 +301,7 @@ def send_course_email(entry_id, email_id, to_list, global_email_context, subtask
     new_subtask_status = None
     try:
         course_title = global_email_context['course_title']
+        start_time = time.time()
         new_subtask_status, send_exception = _send_course_email(
             entry_id,
             email_id,
@@ -302,6 +309,12 @@ def send_course_email(entry_id, email_id, to_list, global_email_context, subtask
             global_email_context,
             subtask_status,
         )
+        log.info(
+            u"BulkEmail ==> _send_course_email completed in : %s for task : %s with recipient count: %s",
+            time.time() - start_time,
+            subtask_status.task_id,
+            len(to_list)
+        )
     except Exception:
         # Unexpected exception. Try to write out the failure to the entry before failing.
         log.exception(u"Send-email task %s for email %s: failed unexpectedly!", current_task_id, email_id)
@@ -504,6 +517,7 @@ def _send_course_email(entry_id, email_id, to_list, global_email_context, subtas
         email_context = {'name': '', 'email': ''}
         email_context.update(global_email_context)
 
+        start_time = time.time()
         while to_list:
             # Update context with user-specific values from the user at the end of the list.
             # At the end of processing this user, they will be popped off of the to_list.
@@ -640,14 +654,15 @@ def _send_course_email(entry_id, email_id, to_list, global_email_context, subtas
 
         log.info(
             u"BulkEmail ==> Task: %s, SubTask: %s, EmailId: %s, Total Successful Recipients: %s/%s, \
-            Failed Recipients: %s/%s",
+            Failed Recipients: %s/%s, Time Taken: %s",
             parent_task_id,
             task_id,
             email_id,
             total_recipients_successful,
             total_recipients,
             total_recipients_failed,
-            total_recipients
+            total_recipients,
+            time.time() - start_time
         )
         duplicate_recipients = [u"{0} ({1})".format(email, repetition)
                                 for email, repetition in recipients_info.most_common() if repetition > 1]

lms/djangoapps/instructor_task/subtasks.py

@@ -4,6 +4,7 @@ This module contains celery task functions for handling the management of subtas
 import json
 import logging
 from contextlib import contextmanager
+from datetime import datetime
 from time import time
 from uuid import uuid4
 
@@ -336,6 +337,10 @@ def queue_subtasks_for_query(
         num_subtasks += 1
         subtask_status = SubtaskStatus.create(subtask_id)
         new_subtask = create_subtask_fcn(item_list, subtask_status)
+        TASK_LOG.info(
+            u"Queueing BulkEmail Task: %s Subtask: %s at timestamp: %s",
+            task_id, subtask_id, datetime.now()
+        )
         new_subtask.apply_async()
 
     # Subtasks have been queued so no exceptions should be raised after this point.