[Checkins] SVN: zc.async/trunk/src/zc/async/ add logging of
callbacks
Gary Poster
gary at zope.com
Mon Apr 21 20:32:12 EDT 2008
Log message for revision 85583:
add logging of callbacks
Changed:
U zc.async/trunk/src/zc/async/CHANGES.txt
U zc.async/trunk/src/zc/async/dispatcher.py
U zc.async/trunk/src/zc/async/dispatcher.txt
U zc.async/trunk/src/zc/async/job.py
U zc.async/trunk/src/zc/async/job.txt
-=-
Modified: zc.async/trunk/src/zc/async/CHANGES.txt
===================================================================
--- zc.async/trunk/src/zc/async/CHANGES.txt 2008-04-22 00:06:23 UTC (rev 85582)
+++ zc.async/trunk/src/zc/async/CHANGES.txt 2008-04-22 00:32:08 UTC (rev 85583)
@@ -10,6 +10,8 @@
- README improved (thanks to Benji York and Sebastian Ware).
+- Callbacks are logged at start and finish in the trace log, including
+ verbose tracebacks if the callback generated a failure.
1.0 (2008-04-09)
================
Modified: zc.async/trunk/src/zc/async/dispatcher.py
===================================================================
--- zc.async/trunk/src/zc/async/dispatcher.py 2008-04-22 00:06:23 UTC (rev 85582)
+++ zc.async/trunk/src/zc/async/dispatcher.py 2008-04-22 00:32:08 UTC (rev 85583)
@@ -157,14 +157,13 @@
local.job = None
transaction.abort()
if info['failed']:
- log = zc.async.utils.tracelog.error
+ zc.async.utils.tracelog.error(
+ '%s failed in thread %d with traceback:\n%s',
+ info['call'], info['thread'], info['result'])
else:
- log = zc.async.utils.tracelog.info
- log(
- '%s %s in thread %d with result:\n%s',
- info['call'],
- info['failed'] and 'failed' or 'succeeded',
- info['thread'], info['result'])
+ zc.async.utils.tracelog.info(
+ '%s succeeded in thread %d with result:\n%s',
+ info['call'], info['thread'], info['result'])
job = self.queue.get()
finally:
conn.close()
Modified: zc.async/trunk/src/zc/async/dispatcher.txt
===================================================================
--- zc.async/trunk/src/zc/async/dispatcher.txt 2008-04-22 00:06:23 UTC (rev 85582)
+++ zc.async/trunk/src/zc/async/dispatcher.txt 2008-04-22 00:32:08 UTC (rev 85583)
@@ -476,7 +476,7 @@
...
>>> print r.getMessage() # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE
<zc.async.job.Job (oid ..., db 'unnamed')
- ``<built-in function mul>(14, None)``> failed in thread ... with result:
+ ``<built-in function mul>(14, None)``> failed in thread ... with traceback:
*--- Failure #... (pickled) ---
.../zc/async/job.py:...: _call_with_retry(...)
[ Locals ]...
Modified: zc.async/trunk/src/zc/async/job.py
===================================================================
--- zc.async/trunk/src/zc/async/job.py 2008-04-22 00:06:23 UTC (rev 85582)
+++ zc.async/trunk/src/zc/async/job.py 2008-04-22 00:32:08 UTC (rev 85583)
@@ -346,9 +346,33 @@
while 1:
for j in callbacks:
if j._status == zc.async.interfaces.NEW:
+ zc.async.utils.tracelog.info(
+ 'starting callback to %r: %r', self, j)
j(self.result)
+ if isinstance(j.result, twisted.python.failure.Failure):
+ zc.async.utils.tracelog.error(
+ 'callback %r to job %r failed with traceback:\n%s',
+ j, self, j.result.getTraceback(
+ elideFrameworkCode=True, detail='verbose'))
+ else:
+ zc.async.utils.tracelog.info(
+ 'callback %r to job %r succeeded with result:\n%s',
+ j, self, j.result)
elif j._status == zc.async.interfaces.ACTIVE:
+ zc.async.utils.tracelog.info(
+ 'failing aborted callback to %r: %r', self, j)
j.fail()
+ if isinstance(j.result, twisted.python.failure.Failure):
+ zc.async.utils.tracelog.error(
+ 'aborted callback %r to job %r failed with '
+ 'traceback:\n%s',
+ j, self, j.result.getTraceback(
+ elideFrameworkCode=True, detail='verbose'))
+ else:
+ zc.async.utils.tracelog.info(
+ 'aborted callback %r to job %r succeeded with '
+ 'result:\n%s',
+ j, self, j.result)
elif j._status == zc.async.interfaces.CALLBACKS:
j.resumeCallbacks()
# TODO: this shouldn't raise anything we want to catch, right?
@@ -356,7 +380,7 @@
# cleaning up dead jobs should look something like the above.
tm.commit()
tm.begin() # syncs
- # it's possible that someone added some callbacks run until
+ # it's possible that someone added some callbacks, so run until
# we're exhausted.
length += len(callbacks)
callbacks = list(self.callbacks)[length:]
Modified: zc.async/trunk/src/zc/async/job.txt
===================================================================
--- zc.async/trunk/src/zc/async/job.txt 2008-04-22 00:06:23 UTC (rev 85582)
+++ zc.async/trunk/src/zc/async/job.txt 2008-04-22 00:32:08 UTC (rev 85583)
@@ -296,7 +296,7 @@
>>> res = j()
success! 15
-...and this one a failure.
+[#callback_log]_ ...and this one a failure.
>>> j = root['j'] = zc.async.job.Job(multiply, 5, None)
>>> transaction.commit()
@@ -305,7 +305,7 @@
>>> res = j() # doctest: +ELLIPSIS
failure. [Failure instance: Traceback: exceptions.TypeError...]
-you can also add multiple callbacks.
+[#errback_log]_ You can also add multiple callbacks.
>>> def also_success(val):
... print "also a success!", val
@@ -896,6 +896,70 @@
...
exceptions.RuntimeError:
+.. [#callback_log] The callbacks are logged
+
+ >>> for r in reversed(trace_logs.records):
+ ... if r.levelname == 'INFO':
+ ... break
+ ... else:
+ ... assert False, 'could not find log'
+ ...
+ >>> print r.getMessage() # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE
+ callback <zc.async.job.Job (oid ..., db 'unnamed')
+ ``zc.async.job.success_or_failure(zc.async.job.Job (oid ..., db 'unnamed'),
+ zc.async.job.Job (oid ..., db 'unnamed'))``>
+ to job <zc.async.job.Job (oid ..., db 'unnamed')
+ ``zc.async.doctest_test.multiply(5, 3)``> succeeded with result:
+ None
+
+
+.. [#errback_log] If the callback receives a failure, but does not fail itself,
+ the log is still just at an "info" level.
+
+ >>> for r in reversed(trace_logs.records):
+ ... if r.levelname == 'INFO':
+ ... break
+ ... else:
+ ... assert False, 'could not find log'
+ ...
+ >>> print r.getMessage() # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE
+ callback <zc.async.job.Job (oid ..., db 'unnamed')
+ ``zc.async.job.success_or_failure(zc.async.job.Job (oid ..., db 'unnamed'),
+ zc.async.job.Job (oid ..., db 'unnamed'))``>
+ to job <zc.async.job.Job (oid ..., db 'unnamed')
+ ``zc.async.doctest_test.multiply(..., None)``> succeeded with result:
+ None
+
+ However, the callbacks that fail themselves are logged at the "error" level
+ and include a detailed traceback.
+
+ >>> j = root['j'] = zc.async.job.Job(multiply, 5, 4)
+ >>> transaction.commit()
+ >>> cb = j.addCallback(zc.async.job.Job(multiply)) # will miss one argument
+ >>> j() # doctest: +ELLIPSIS
+ 20
+
+ >>> for r in reversed(trace_logs.records):
+ ... if r.levelname == 'ERROR':
+ ... break
+ ... else:
+ ... assert False, 'could not find log'
+ ...
+ >>> print r.getMessage() # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE
+ callback <...Job...``zc.async.doctest_test.multiply()``> ... failed with traceback:
+ *--- Failure #... (pickled) ---
+ .../zc/async/job.py:...
+ [ Locals...
+ res : 'None...
+ ( Globals...
+ .../zc/async/job.py:...
+ [ Locals...
+ effective_args : '[20]...
+ ( Globals...
+ exceptions.TypeError: multiply() takes at least 2 arguments (1 given)
+ *--- End of Failure #... ---
+ <BLANKLINE>
+
.. [#call_self] Here's a job trying to call itself.
>>> def call(obj, *ignore):
More information about the Checkins
mailing list