Merge pull request #16744 from edx/thallada/highlights-logging

Schedules: more info logging and add exception logging

openedx/core/djangoapps/schedules/resolvers.py

@@ -136,13 +136,13 @@ class BinnedSchedulesBaseResolver(PrefixedDebugLoggerMixin, RecipientResolver):
         if "read_replica" in settings.DATABASES:
             schedules = schedules.using("read_replica")
 
-        LOG.debug('Query = %r', schedules.query.sql_with_params())
+        LOG.info('Query = %r', schedules.query.sql_with_params())
 
         with function_trace('schedule_query_set_evaluation'):
             # This will run the query and cache all of the results in memory.
             num_schedules = len(schedules)
 
-        LOG.debug('Number of schedules = %d', num_schedules)
+        LOG.info('Number of schedules = %d', num_schedules)
 
         # This should give us a sense of the volume of data being processed by each task.
         set_custom_metric('num_schedules', num_schedules)
@@ -356,7 +356,11 @@ class CourseUpdateResolver(BinnedSchedulesBaseResolver):
             try:
                 week_highlights = get_week_highlights(user, enrollment.course_id, week_num)
             except CourseUpdateDoesNotExist:
-                continue
+                LOG.exception(
+                    'Weekly highlights for user {} in week {} of course {} does not exist or is disabled'.format(
+                        user, week_num, enrollment.course_id
+                    )
+                )
 
             template_context.update({
                 'course_name': schedule.enrollment.course.display_name,

openedx/core/djangoapps/schedules/tasks.py

@@ -64,18 +64,28 @@ class ScheduleMessageBaseTask(Task):
 
     @classmethod
     def log_debug(cls, message, *args, **kwargs):
+        """
+        Wrapper around LOG.debug that prefixes the message.
+        """
         LOG.debug(cls.log_prefix + ': ' + message, *args, **kwargs)
 
     @classmethod
+    def log_info(cls, message, *args, **kwargs):
+        """
+        Wrapper around LOG.info that prefixes the message.
+        """
+        LOG.info(cls.log_prefix + ': ' + message, *args, **kwargs)
+
+    @classmethod
     def enqueue(cls, site, current_date, day_offset, override_recipient_email=None):
         current_date = resolvers._get_datetime_beginning_of_day(current_date)
 
         if not cls.is_enqueue_enabled(site):
-            cls.log_debug('Message queuing disabled for site %s', site.domain)
+            cls.log_info('Message queuing disabled for site %s', site.domain)
             return
 
         target_date = current_date + datetime.timedelta(days=day_offset)
-        cls.log_debug('Target date = %s', target_date.isoformat())
+        cls.log_info('Target date = %s', target_date.isoformat())
         for bin in range(cls.num_bins):
             task_args = (
                 site.id,
@@ -84,7 +94,7 @@ class ScheduleMessageBaseTask(Task):
                 bin,
                 override_recipient_email,
             )
-            cls.log_debug('Launching task with args = %r', task_args)
+            cls.log_info('Launching task with args = %r', task_args)
             cls.apply_async(
                 task_args,
                 retry=False,
@@ -218,7 +228,7 @@ def _is_delivery_enabled(site, delivery_config_var, log_prefix):
     if getattr(ScheduleConfig.current(site), delivery_config_var, False):
         return True
     else:
-        LOG.debug('%s: Message delivery disabled for site %s', log_prefix, site.domain)
+        LOG.info('%s: Message delivery disabled for site %s', log_prefix, site.domain)
 
 
 def _annotate_for_monitoring(message_type, site, bin_num, target_day_str, day_offset):

openedx/core/djangoapps/schedules/tests/test_tasks.py

@@ -29,7 +29,7 @@ class TestScheduleMessageBaseTask(CacheIsolationTestCase):
         with patch.multiple(
             self.basetask,
             is_enqueue_enabled=Mock(return_value=False),
-            log_debug=DEFAULT,
+            log_info=DEFAULT,
             run=send,
         ) as patches:
             self.basetask.enqueue(
@@ -37,7 +37,7 @@ class TestScheduleMessageBaseTask(CacheIsolationTestCase):
                 current_date=datetime.datetime.now(),
                 day_offset=2
             )
-            patches['log_debug'].assert_called_once_with(
+            patches['log_info'].assert_called_once_with(
                 'Message queuing disabled for site %s', self.site.domain)
             send.apply_async.assert_not_called()
 
@@ -48,7 +48,7 @@ class TestScheduleMessageBaseTask(CacheIsolationTestCase):
         with patch.multiple(
             self.basetask,
             is_enqueue_enabled=Mock(return_value=True),
-            log_debug=DEFAULT,
+            log_info=DEFAULT,
             run=send,
         ) as patches:
             self.basetask.enqueue(
@@ -58,8 +58,7 @@ class TestScheduleMessageBaseTask(CacheIsolationTestCase):
             )
             target_date = current_date.replace(hour=0, minute=0, second=0, microsecond=0) + \
                 datetime.timedelta(day_offset)
-            print(patches['log_debug'].mock_calls)
-            patches['log_debug'].assert_any_call(
+            patches['log_info'].assert_any_call(
                 'Target date = %s', target_date.isoformat())
             assert send.call_count == DEFAULT_NUM_BINS
 

openedx/core/djangoapps/schedules/utils.py

@@ -14,4 +14,13 @@ class PrefixedDebugLoggerMixin(object):
             self.log_prefix = self.__class__.__name__
 
     def log_debug(self, message, *args, **kwargs):
+        """
+        Wrapper around LOG.debug that prefixes the message.
+        """
         LOG.debug(self.log_prefix + ': ' + message, *args, **kwargs)
+
+    def log_info(self, message, *args, **kwargs):
+        """
+        Wrapper around LOG.info that prefixes the message.
+        """
+        LOG.info(self.log_prefix + ': ' + message, *args, **kwargs)