[Checkins] SVN: lovely.remotetask/trunk/src/lovely/remotetask/ Better error reporting in case of an exception in a task.

Jürgen Kartnaller juergen at kartnaller.at
Sat Jun 2 15:31:49 EDT 2007


Log message for revision 76173:
  Better error reporting in case of an exception in a task.
  
  If a task raises an exeption the job is repeated 3 times. Then the job status
  is changed to error.
  

Changed:
  U   lovely.remotetask/trunk/src/lovely/remotetask/browser/README.txt
  U   lovely.remotetask/trunk/src/lovely/remotetask/ftesting.zcml
  U   lovely.remotetask/trunk/src/lovely/remotetask/service.py
  U   lovely.remotetask/trunk/src/lovely/remotetask/testing.py
  U   lovely.remotetask/trunk/src/lovely/remotetask/xmlrpc.txt

-=-
Modified: lovely.remotetask/trunk/src/lovely/remotetask/browser/README.txt
===================================================================
--- lovely.remotetask/trunk/src/lovely/remotetask/browser/README.txt	2007-06-02 19:24:52 UTC (rev 76172)
+++ lovely.remotetask/trunk/src/lovely/remotetask/browser/README.txt	2007-06-02 19:31:48 UTC (rev 76173)
@@ -105,3 +105,98 @@
   >>> browser.getControl('Remove all').click()
   >>> 'Cleaned 1 Jobs' in  browser.contents
   True
+
+
+Thread Exception Reporting
+--------------------------
+
+If a job raises an exception the task service repeats the job 3 times. On
+every exception a traceback is written to the log.
+
+We modify the python logger to get the log output.
+
+  >>> import logging
+  >>> logger = logging.getLogger("lovely.remotetask")
+  >>> logger.setLevel(logging.ERROR)
+  >>> import StringIO
+  >>> io = StringIO.StringIO()
+  >>> ch = logging.StreamHandler(io)
+  >>> ch.setLevel(logging.DEBUG)
+  >>> logger.addHandler(ch)
+
+  >>> from time import sleep
+  >>> from zope import component
+  >>> from lovely.remotetask.interfaces import ITaskService
+  >>> service = getRootFolder()['tasks']
+
+We add e job for a task which raises a ZeroDivisionError every time it is
+called.
+
+  >>> jobid = service.add(u'exception')
+  >>> service.getStatus(jobid)
+  'queued'
+  >>> import transaction
+  >>> transaction.commit()
+  >>> service.startProcessing()
+  >>> transaction.commit()
+  >>> sleep(1.5)
+  >>> service.stopProcessing()
+  >>> transaction.commit()
+
+We got log entries with the tracebacks of the division error.
+
+  >>> logvalue = io.getvalue()
+  >>> print logvalue
+  catched a generic exception, preventing thread from crashing
+  integer division or modulo by zero
+  Traceback (most recent call last):
+  ...
+  ZeroDivisionError: integer division or modulo by zero
+  <BLANKLINE>
+
+We had 3 retries.
+
+  >>> logvalue.count('ZeroDivisionError')
+  3
+
+The job status is set to 'error'.
+
+  >>> service.getStatus(jobid)
+  'error'
+
+We do the same again to see if the same thin happens again. This test is
+necessary to see if the internal runCount in the task service is reset.
+
+  >>> io.seek(0)
+  >>> jobid = service.add(u'exception')
+  >>> service.getStatus(jobid)
+  'queued'
+  >>> import transaction
+  >>> transaction.commit()
+  >>> service.startProcessing()
+  >>> transaction.commit()
+  >>> sleep(1.5)
+  >>> service.stopProcessing()
+  >>> transaction.commit()
+
+We got log entries with the tracebacks of the division error.
+
+  >>> logvalue = io.getvalue()
+  >>> print logvalue
+  catched a generic exception, preventing thread from crashing
+  integer division or modulo by zero
+  Traceback (most recent call last):
+  ...
+  ZeroDivisionError: integer division or modulo by zero
+  <BLANKLINE>
+
+We had 3 retries.
+
+  >>> logvalue.count('ZeroDivisionError')
+  3
+
+The job status is set to 'error'.
+
+  >>> service.getStatus(jobid)
+  'error'
+

Modified: lovely.remotetask/trunk/src/lovely/remotetask/ftesting.zcml
===================================================================
--- lovely.remotetask/trunk/src/lovely/remotetask/ftesting.zcml	2007-06-02 19:24:52 UTC (rev 76172)
+++ lovely.remotetask/trunk/src/lovely/remotetask/ftesting.zcml	2007-06-02 19:31:48 UTC (rev 76173)
@@ -19,6 +19,10 @@
   <include package="lovely.remotetask" />
   <include package="zope.app.xmlrpcintrospection" />
 
+  <utility
+      factory="lovely.remotetask.testing.ExceptionTask"
+      name="exception" />
+
   <securityPolicy
       component="zope.app.securitypolicy.zopepolicy.ZopeSecurityPolicy" />
   <include package="zope.app.securitypolicy" />

Modified: lovely.remotetask/trunk/src/lovely/remotetask/service.py
===================================================================
--- lovely.remotetask/trunk/src/lovely/remotetask/service.py	2007-06-02 19:24:52 UTC (rev 76172)
+++ lovely.remotetask/trunk/src/lovely/remotetask/service.py	2007-06-02 19:31:48 UTC (rev 76173)
@@ -39,6 +39,9 @@
 
 log = logging.getLogger('lovely.remotetask')
 
+storage = threading.local()
+
+
 class TaskService(contained.Contained, persistent.Persistent):
     """A persistent task service.
 
@@ -169,6 +172,9 @@
             raise IndexError
         jobtask = component.getUtility(self.taskInterface, name=job.task)
         job.started = datetime.datetime.now()
+        if not hasattr(storage, 'runCount'):
+            storage.runCount = 0
+        storage.runCount += 1
         try:
             job.output = jobtask(self, job.id, job.input)
             if job.status != interfaces.CRONJOB:
@@ -177,7 +183,18 @@
             job.error = error
             if job.status != interfaces.CRONJOB:
                 job.status = interfaces.ERROR
+        except Exception, error:
+            if storage.runCount <= 3:
+                log.error(
+                    'catched a generic exception, preventing thread from crashing')
+                log.exception(error)
+                raise
+            else:
+                job.error = error
+                if job.status != interfaces.CRONJOB:
+                    job.status = interfaces.ERROR
         job.completed = datetime.datetime.now()
+        storage.runCount = 0
         return True
 
     def process(self, now=None):
@@ -252,10 +269,8 @@
         except IndexError:
             log.debug('waiting for next %s task'% path[1])
             time.sleep(1)
-        except Exception, e:
+        except:
             # This thread should never crash, thus a blank except
-            log.error('catched a generic exception, preventing thread from \
-                       crashing: %s'% e)
             pass
 
 def getAutostartServiceNames():

Modified: lovely.remotetask/trunk/src/lovely/remotetask/testing.py
===================================================================
--- lovely.remotetask/trunk/src/lovely/remotetask/testing.py	2007-06-02 19:24:52 UTC (rev 76172)
+++ lovely.remotetask/trunk/src/lovely/remotetask/testing.py	2007-06-02 19:31:48 UTC (rev 76173)
@@ -27,6 +27,18 @@
 from lovely.remotetask import interfaces, job, task
 
 
+class ExceptionTask(object):
+    """Task to test exception handling"""
+    zope.interface.implements(interfaces.ITask)
+
+    def __call__(self, service, id, input):
+        # always raise division by zero
+        1/0
+
+    def __repr__(self):
+        return '<%s>' %(self.__class__.__name__)
+
+
 ###############################################################################
 #
 # Stub implementations (Note: use the ITaskStub interface for this service)

Modified: lovely.remotetask/trunk/src/lovely/remotetask/xmlrpc.txt
===================================================================
--- lovely.remotetask/trunk/src/lovely/remotetask/xmlrpc.txt	2007-06-02 19:24:52 UTC (rev 76172)
+++ lovely.remotetask/trunk/src/lovely/remotetask/xmlrpc.txt	2007-06-02 19:31:48 UTC (rev 76173)
@@ -51,7 +51,7 @@
   ... </methodCall>
   ... """)
   HTTP/1.0 200 Ok
-  Content-Length: 213
+  Content-Length: 255
   Content-Type: text/xml;charset=utf-8
   <BLANKLINE>
   <?xml version='1.0'?>
@@ -61,6 +61,7 @@
   <value><array><data>
   <value><string>echo</string></value>
   <value><string>error</string></value>
+  <value><string>exception</string></value>
   </data></array></value>
   </param>
   </params>



More information about the Checkins mailing list