Merge pull request #83 from spilgames/logging

OPT improved logging

job_runner/apps/job_runner/auth.py

@@ -1,13 +1,16 @@
 import hashlib
 import hmac
 import re
+import logging
 
 from django.db.models import Q
 from tastypie.authentication import Authentication
 from tastypie.authorization import Authorization
 
 from job_runner.apps.job_runner.models import Worker
 
+logger = logging.getLogger(__name__)
+
 
 def validate_hmac(request):
     """
@@ -37,11 +40,13 @@ def validate_hmac(request):
     api_key_match = re.match(r'^ApiKey (.*?):(.*?)$', auth_header)
 
     if not api_key_match:
+        logger.error('api key mismatch')
         return False
 
     try:
         worker = Worker.objects.get(api_key=api_key_match.group(1))
     except Worker.DoesNotExist:
+        logger.error('worker does not exist')
         return False
 
     hmac_message = '{request_method}{full_path}{request_body}'.format(
@@ -56,6 +61,8 @@ def validate_hmac(request):
     if expected_hmac.hexdigest() == api_key_match.group(2):
         return True
 
+    logger.error('hmac mismatch')
+
     return False
 
 

job_runner/apps/job_runner/management/commands/broadcast_queue.py

@@ -162,7 +162,7 @@ def _broadcast_kill_requests(self):
                     'action': 'kill',
                 })
             ]
-            logger.debug('Sending: {0}'.format(message))
+            logger.info('Sending: {0}'.format(message))
             self.publisher.send_multipart(message)
 
     def _broadcast_worker_ping(self):

job_runner/apps/job_runner/models.py

@@ -1,5 +1,6 @@
 import calendar
 from datetime import timedelta
+import logging
 
 from django.conf import settings
 from django.contrib.auth.models import Group
@@ -15,6 +16,8 @@
 from job_runner.apps.job_runner.signals import post_run_update, post_run_create
 from job_runner.apps.job_runner.utils import correct_dst_difference
 
+logger = logging.getLogger(__name__)
+
 
 RESCHEDULE_INTERVAL_TYPE_CHOICES = (
     ('MINUTE', 'Every x minutes'),
@@ -161,6 +164,7 @@ def is_responsive(self):
             if self.ping_response_dts + acceptable_delta >= timezone.now():
                 return True
 
+        logger.error('Worker {0} is not responsive'.format(self.title))
         return False
 
     class Meta:
@@ -386,6 +390,8 @@ def schedule(self, dts=None):
         if not dts:
             dts = timezone.now()
 
+        logger.info('Scheduling {0} on {1}'.format(self.title, dts))
+
         Run.objects.create(
             job=self,
             schedule_dts=dts,
@@ -416,8 +422,12 @@ def reschedule(self):
         # since we are pre-scheduling (a new run is created, before the
         # scheduled run is sent to the worker), having one schedule id is valid
         if len(active_schedule_ids) > 1:
+            logging.error('Multiple ({0}) active schedule ids'.format(
+                active_schedule_ids))
             return
 
+        logger.info('Attempting rescheduling {0}'.format(self.title))
+
         # check if job is setup for re-scheduling
         if self.reschedule_interval_type and self.reschedule_interval:
             try:
@@ -426,6 +436,8 @@ def reschedule(self):
                 last_run = self.run_set.filter(
                     is_manual=False).order_by('-pk')[0]
             except IndexError:
+                logger.error('Reschedule failed for {0}: IndexError'.format(
+                    self.title))
                 return
 
             try:
@@ -438,7 +450,12 @@ def reschedule(self):
                     last_run.schedule_dts, reschedule_date)
 
                 self.schedule(reschedule_date)
+                logger.info('Rescheduled {0} for {1}'.format(
+                    self.title, reschedule_date))
             except RescheduleException:
+                logger.error(
+                    'Reschedule failed for {0}: RescheduleException'.format(
+                        self.title))
                 notifications.reschedule_failed(self)
 
     def _get_reschedule_incremented_dts(self, increment_date):
@@ -608,8 +625,10 @@ def mark_failed(self, message):
         self.return_dts = timezone.now()
         self.return_success = False
 
-        log_message = 'This run was marked as failed. Reason: {0}'.format(
-            message)
+        log_message = 'This run for {0} was marked as failed. \
+            Reason: {1}'.format(
+            self.job.title, message)
+        logger.error(log_message)
 
         try:
             # In rare cases, it is possible that there is already a log for

job_runner/apps/job_runner/tests/functional/test_models.py

@@ -320,8 +320,8 @@ def test_mark_failed(self):
 
         run = Run.objects.get(pk=1)
 
-        self.assertEqual(
-            'This run was marked as failed. Reason: Test mark failed',
+        self.assertNotEqual(
+            '',
             run.run_log.content
         )
         self.assertIsInstance(run.enqueue_dts, datetime)