Merge pull request binarymatt#113 from joeshaw/joeshaw-logging

Some logging tweaks

Author: binarymatt

pyres/__init__.py

@@ -20,7 +20,7 @@ def get_logging_handler(filename, procname, namespace=None):
         message_format = namespace + ': %(message)s'
     else:
         message_format = '%(message)s'
-    format = '%(asctime)s %(levelname)-8s ' + message_format
+    format = '%(asctime)s %(process)5d %(levelname)-8s ' + message_format
 
     if not filename:
         filename = "stderr"

pyres/job.py

@@ -1,3 +1,4 @@
+import logging
 import time
 from datetime import timedelta
 from pyres import ResQ, safe_str_to_class
@@ -88,6 +89,7 @@ def perform(self):
                 raise
             else:
                 metadata["retried"] = True
+                logging.exception("Retry scheduled after error in %s", job)
         finally:
             after_perform = getattr(payload_class, "after_perform", None)
             if after_perform and check_after:

pyres/scheduler.py

@@ -66,7 +66,7 @@ def next_item(self, timestamp):
     def handle_delayed_items(self):
         for timestamp in self.next_timestamp():
             _setproctitle('Handling timestamp %s' % timestamp)
-            logger.info('handling timestamp: %s' % timestamp)
+            logger.debug('handling timestamp: %s' % timestamp)
             for item in self.next_item(timestamp):
                 logger.debug('queueing item %s' % item)
                 klass = item['class']

pyres/worker.py

@@ -22,9 +22,9 @@ class and passes a comma-separated list of queues to listen on.::
        >>> Worker.run([queue1, queue2], server="localhost:6379")
 
     """
-    
+
     job_class = Job
-    
+
     def __init__(self, queues=(), server="localhost:6379", password=None, timeout=None):
         self.queues = queues
         self.validate_queues()
@@ -130,6 +130,7 @@ def work(self, interval=5):
 
         """
         self._setproctitle("Starting")
+        logger.info("starting")
         self.startup()
 
         while True:
@@ -209,10 +210,10 @@ def fork_worker(self, job):
             logger.debug('done waiting')
         else:
             self._setproctitle("Processing %s since %s" %
-                               (job._queue,
+                               (job,
                                 datetime.datetime.now()))
             logger.info('Processing %s since %s' %
-                         (job._queue, datetime.datetime.now()))
+                         (job, datetime.datetime.now()))
             self.after_fork(job)
 
             # re-seed the Python PRNG after forking, otherwise
@@ -260,10 +261,10 @@ def process(self, job=None):
                     self._handle_job_exception(job)
 
             if not job_failed:
-                logger.info('completed job')
+                logger.debug('completed job')
                 logger.debug('job details: %s' % job)
         finally:
-            self.done_working()
+            self.done_working(job)
 
     def _handle_job_exception(self, job):
         exceptionType, exceptionValue, exceptionTraceback = sys.exc_info()
@@ -290,8 +291,8 @@ def working_on(self, job):
         logger.debug("worker:%s" % str(self))
         logger.debug(self.resq.redis["resque:worker:%s" % str(self)])
 
-    def done_working(self):
-        logger.info('done working')
+    def done_working(self, job):
+        logger.debug('done working on %s', job)
         self.processed()
         self.resq.redis.delete("resque:worker:%s" % str(self))