<br><div class="gmail_quote">On Thu, Jun 28, 2012 at 9:40 PM, Dan Stromberg <span dir="ltr">&lt;<a href="mailto:drsalists@gmail.com" target="_blank">drsalists@gmail.com</a>&gt;</span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div style="margin-left:40px"><br></div>Hi.<br><br>I&#39;m a Twisted neophyte, but I&#39;ve been using Python a long time.<br><br>My question:<br>
<div style="margin-left:40px">Is there a way of producing a deferred 
graph in a Python program at a given point in time?  Perhaps something 
based on graphviz and objgraph.py?  We&#39;re able to detect when we&#39;re 
having the problem, we just don&#39;t (yet) know its cause.<br>
</div>
<br><br>Background:<br><div style="margin-left:40px">I&#39;m looking at some code with a bit over 200 addCallback/addErrback/addCallbacks in it.<br><br>It&#39;s got a problem where sometimes the deferreds seem to just stop executing.  I see in the doc it says that this can happen if you&#39;ve neglected to add an errback to the end of one or more of your deferred chains.<br>

<br>One of the people who&#39;s been here longer than me, indicated that he&#39;s gone through the code looking for such issues, and didn&#39;t find any.  This suggests to me that either there&#39;s some other cause, or that it really is a deferred without a final errback, but it&#39;s hidden in a dark corner of the code somewhere.<br>

</div><br><br>Thanks!<br><br>
</blockquote></div>I put together something to do a single-point-in-time graph (as distorted/delayed by the time it takes to go through all the objects in the python interpreter) of deferreds.  Please find it below as a shar archive (wow, someone still does those?   Yeah, sometimes)  Anyway, given a tree of deferreds, this will produce a whatever.dot file, which can be fed to graphviz&#39; &quot;dot -Tpdf whatever.dot &gt; whatever.pdf&quot;, and the pdf has a rather nice-looking graph of the deferreds.<br>
<br>#!/bin/sh<br># This is a shell archive (produced by GNU sharutils 4.11.1).<br># To extract the files from this archive, save it to some FILE, remove<br># everything before the `#!/bin/sh&#39; line above, then type `sh FILE&#39;.<br>
#<br>lock_dir=_sh32156<br># Made on 2012-07-02 21:48 UTC by &lt;stromberg@aw50&gt;.<br># Source directory was `/home/stromberg/src/twisted-experiments&#39;.<br>#<br># Existing files will *not* be overwritten, unless `-c&#39; is specified.<br>
#<br># This shar contains:<br># length mode       name<br># ------ ---------- ------------------------------------------<br>#   2181 -rwxr-xr-x deferreddump.py<br>#   3174 -rwxr-xr-x wedgedump<br>#<br>MD5SUM=${MD5SUM-md5sum}<br>
f=`${MD5SUM} --version | egrep &#39;^md5sum .*(core|text)utils&#39;`<br>test -n &quot;${f}&quot; &amp;&amp; md5check=true || md5check=false<br>${md5check} || \<br>  echo &#39;Note: not verifying md5sums.  Consider installing GNU coreutils.&#39;<br>
if test &quot;X$1&quot; = &quot;X-c&quot;<br>then keep_file=&#39;&#39;<br>else keep_file=true<br>fi<br>echo=echo<br>save_IFS=&quot;${IFS}&quot;<br>IFS=&quot;${IFS}:&quot;<br>gettext_dir=<br>locale_dir=<br>set_echo=false<br>
<br>for dir in $PATH<br>do<br>  if test -f $dir/gettext \<br>     &amp;&amp; ($dir/gettext --version &gt;/dev/null 2&gt;&amp;1)<br>  then<br>    case `$dir/gettext --version 2&gt;&amp;1 | sed 1q` in<br>      *GNU*) gettext_dir=$dir<br>
      set_echo=true<br>      break ;;<br>    esac<br>  fi<br>done<br><br>if ${set_echo}<br>then<br>  set_echo=false<br>  for dir in $PATH<br>  do<br>    if test -f $dir/shar \<br>       &amp;&amp; ($dir/shar --print-text-domain-dir &gt;/dev/null 2&gt;&amp;1)<br>
    then<br>      locale_dir=`$dir/shar --print-text-domain-dir`<br>      set_echo=true<br>      break<br>    fi<br>  done<br><br>  if ${set_echo}<br>  then<br>    TEXTDOMAINDIR=$locale_dir<br>    export TEXTDOMAINDIR<br>
    TEXTDOMAIN=sharutils<br>    export TEXTDOMAIN<br>    echo=&quot;$gettext_dir/gettext -s&quot;<br>  fi<br>fi<br>IFS=&quot;$save_IFS&quot;<br>if (echo &quot;testing\c&quot;; echo 1,2,3) | grep c &gt;/dev/null<br>then if (echo -n test; echo 1,2,3) | grep n &gt;/dev/null<br>
     then shar_n= shar_c=&#39;<br>&#39;<br>     else shar_n=-n shar_c= ; fi<br>else shar_n= shar_c=&#39;\c&#39; ; fi<br>f=shar-touch.$$<br>st1=200112312359.59<br>st2=123123592001.59<br>st2tr=123123592001.5 # old SysV 14-char limit<br>
st3=1231235901<br><br>if touch -am -t ${st1} ${f} &gt;/dev/null 2&gt;&amp;1 &amp;&amp; \<br>   test ! -f ${st1} &amp;&amp; test -f ${f}; then<br>  shar_touch=&#39;touch -am -t $1$2$3$4$5$6.$7 &quot;$8&quot;&#39;<br><br>elif touch -am ${st2} ${f} &gt;/dev/null 2&gt;&amp;1 &amp;&amp; \<br>
   test ! -f ${st2} &amp;&amp; test ! -f ${st2tr} &amp;&amp; test -f ${f}; then<br>  shar_touch=&#39;touch -am $3$4$5$6$1$2.$7 &quot;$8&quot;&#39;<br><br>elif touch -am ${st3} ${f} &gt;/dev/null 2&gt;&amp;1 &amp;&amp; \<br>
   test ! -f ${st3} &amp;&amp; test -f ${f}; then<br>  shar_touch=&#39;touch -am $3$4$5$6$2 &quot;$8&quot;&#39;<br><br>else<br>  shar_touch=:<br>  echo<br>  ${echo} &#39;WARNING: not restoring timestamps.  Consider getting and<br>
installing GNU `touch&#39;\&#39;&#39;, distributed in GNU coreutils...&#39;<br>  echo<br>fi<br>rm -f ${st1} ${st2} ${st2tr} ${st3} ${f}<br>#<br>if test ! -d ${lock_dir} ; then :<br>else ${echo} &quot;lock directory ${lock_dir} exists&quot;<br>
     exit 1<br>fi<br>if mkdir ${lock_dir}<br>then ${echo} &quot;x - created lock directory ${lock_dir}.&quot;<br>else ${echo} &quot;x - failed to create lock directory ${lock_dir}.&quot;<br>     exit 1<br>fi<br># ============= deferreddump.py ==============<br>
if test -n &quot;${keep_file}&quot; &amp;&amp; test -f &#39;deferreddump.py&#39;<br>then<br>${echo} &quot;x - SKIPPING deferreddump.py (file already exists)&quot;<br>else<br>${echo} &quot;x - extracting deferreddump.py (text)&quot;<br>
  sed &#39;s/^X//&#39; &lt;&lt; &#39;SHAR_EOF&#39; &gt; &#39;deferreddump.py&#39; &amp;&amp;<br>#!/usr/bin/python<br>X<br># See also: <a href="http://twistedmatrix.com/trac/ticket/3858">http://twistedmatrix.com/trac/ticket/3858</a><br>
# and:      <a href="http://twistedmatrix.com/trac/ticket/1402">http://twistedmatrix.com/trac/ticket/1402</a><br># and:<br>#   twisted.internet.defer also exposes a setDebugging(bool) function to<br>#   store call stacks from creation and invocation in deferred objects,<br>
#   it&#39;s what I was using to try and figure out what was going on, but<br>#   it&#39;s not nearly as at-a-glance as a graph is.<br>X<br>import gc<br>import sys<br>X<br>import twisted.internet.defer<br>X<br>def escape(callback_type, obj):<br>
X    dummy = callback_type<br>X    return &#39;%s&#39; % (str(obj).replace(&#39; &#39;, &#39;_&#39;).replace(&#39;:&#39;, &#39;&#39;).replace(&#39;&lt;&#39;, &#39;&#39;).replace(&#39;&gt;&#39;, &#39;&#39;), )<br>X<br>def dump(outfile = sys.stdout):<br>
X    outfile.write(&#39;digraph deferred_digraph {\n&#39;)<br>X    for obj in gc.get_objects():<br>X        if isinstance(obj, twisted.internet.defer.Deferred):<br>X            len_callbacks = len(obj.callbacks)<br>X            if obj.callbacks:<br>
X                outfile.write(&#39;\t%s -&gt; %s\n&#39; % (escape(&#39;&#39;, obj), escape(&#39;&#39;, obj.callbacks[0][0][0])))<br>X                outfile.write(&#39;\t%s -&gt; %s\n&#39; % (escape(&#39;&#39;, obj), escape(&#39;&#39;, obj.callbacks[0][1][0])))<br>
X            for callbackpairno in range(len_callbacks - 1):<br>X                current_callback = obj.callbacks[callbackpairno][0]<br>X                current_errback = obj.callbacks[callbackpairno][1]<br>X                current_callback_desc = current_callback[0]<br>
X                current_errback_desc = current_errback[0]<br>X<br>X                next_callback = obj.callbacks[callbackpairno + 1][0]<br>X                next_errback = obj.callbacks[callbackpairno + 1][1]<br>X                next_callback_desc = next_callback[0]<br>
X                next_errback_desc = next_errback[0]<br>X<br>X                outfile.write(&#39;\t%s -&gt; %s;\n&#39; % (escape(&#39;callback&#39;, current_callback_desc), escape(&#39;callback&#39;, next_callback_desc)))<br>
X                outfile.write(&#39;\t%s -&gt; %s;\n&#39; % (escape(&#39;errback&#39;, current_errback_desc), escape(&#39;errback&#39;, next_errback_desc)))<br>X<br>X                outfile.write(&#39;\t%s -&gt; %s;\n&#39; % (escape(&#39;callback&#39;, current_callback_desc), escape(&#39;errback&#39;, next_errback_desc)))<br>
X                outfile.write(&#39;\t%s -&gt; %s;\n&#39; % (escape(&#39;errback&#39;, current_errback_desc), escape(&#39;callback&#39;, next_callback_desc)))<br>X<br>X    outfile.write(&#39;}\n&#39;)<br>X<br>X<br>SHAR_EOF<br>
  (set 20 12 06 29 18 02 00 &#39;deferreddump.py&#39;<br>   eval &quot;${shar_touch}&quot;) &amp;&amp; \<br>  chmod 0755 &#39;deferreddump.py&#39;<br>if test $? -ne 0<br>then ${echo} &quot;restore of deferreddump.py failed&quot;<br>
fi<br>  if ${md5check}<br>  then (<br>       ${MD5SUM} -c &gt;/dev/null 2&gt;&amp;1 || ${echo} &#39;deferreddump.py&#39;: &#39;MD5 check failed&#39;<br>       ) &lt;&lt; \SHAR_EOF<br>45b2aed37cc2e57bc58f46a42eb2a2d4  deferreddump.py<br>
SHAR_EOF<br>  else<br>test `LC_ALL=C wc -c &lt; &#39;deferreddump.py&#39;` -ne 2181 &amp;&amp; \<br>  ${echo} &quot;restoration warning:  size of &#39;deferreddump.py&#39; is not 2181&quot;<br>  fi<br>fi<br># ============= wedgedump ==============<br>
if test -n &quot;${keep_file}&quot; &amp;&amp; test -f &#39;wedgedump&#39;<br>then<br>${echo} &quot;x - SKIPPING wedgedump (file already exists)&quot;<br>else<br>${echo} &quot;x - extracting wedgedump (text)&quot;<br>  sed &#39;s/^X//&#39; &lt;&lt; &#39;SHAR_EOF&#39; &gt; &#39;wedgedump&#39; &amp;&amp;<br>
#!/usr/bin/python<br>X<br># Unhandled Errors<br>X<br># From <a href="http://twistedmatrix.com/documents/current/core/howto/defer.html">http://twistedmatrix.com/documents/current/core/howto/defer.html</a> :<br>X<br>#   If a Deferred is garbage-collected with an unhandled error (i.e. it<br>
#   would call the next errback if there was one), then Twisted will write<br>#   the error&#39;s traceback to the log file. This means that you can<br>#   typically get away with not adding errbacks and still get errors<br>
#   logged. Be careful though; if you keep a reference to the Deferred<br>#   around, preventing it from being garbage-collected, then you may never<br>#   see the error (and your callbacks will mysteriously seem to have never<br>
#   been called). If unsure, you should explicitly add an errback after<br>#   your callbacks, even if all you do is:<br>X<br>#       # Make sure errors get logged<br>#       from twisted.python import log<br>#       d.addErrback(log.err)<br>
X<br>import sys<br>#mport time<br>X<br>import twisted.internet.defer<br>import twisted.python<br>X<br>import deferreddump<br>X<br>def get_deferred():<br>X    return twisted.internet.defer.succeed(1)<br>X<br>def cb1(value):<br>
X    print value<br>X    return value * 2<br>X<br>def cb2(value):<br>X    #raise ValueError<br>X    print value<br>X    return value * 2<br>X<br>def cb3(value):<br>X    print value<br>X    return value * 2<br>X<br>def cb4(value):<br>
X    print value<br>X    return value * 2<br>X<br>def cb5(value):<br>X    print value<br>X    return value * 2<br>X<br>def cb6(value):<br>X    print value<br>X    return value * 2<br>X<br>def cb7(value):<br>X    print value<br>
X    return value * 2<br>X<br>def cb8(value):<br>X    print value<br>X    return value * 2<br>X<br>def eb1(value):<br>X    twisted.python.log.err()<br>X<br>def eb2(value):<br>X    twisted.python.log.err()<br>X<br>def eb3(value):<br>
X    twisted.python.log.err()<br>X<br>def eb4(value):<br>X    twisted.python.log.err()<br>X<br>def eb5(value):<br>X    twisted.python.log.err()<br>X<br>def eb6(value):<br>X    twisted.python.log.err()<br>X<br>def eb7(value):<br>
X    twisted.python.log.err()<br>X<br>def eb8(value):<br>X    twisted.python.log.err()<br>X<br>def arbitrary_function(add_final_log):<br>X    deferred = get_deferred()<br>X<br>X    # apparently we can use the same callback multiple times in the same deferred<br>
X    first_deferred = deferred.addCallback(cb1)<br>X    first_deferred.pause()<br>X    deferred.addCallbacks(cb1, eb1)<br>X    deferred.addCallbacks(cb2, eb2)<br>X    deferred.addCallbacks(cb3, eb3)<br>X    deferred.addCallbacks(cb4, eb4)<br>
X    deferred.addCallbacks(cb5, eb5)<br>X    deferred.addCallbacks(cb6, eb6)<br>X    deferred.addCallbacks(cb7, eb7)<br>X<br>X    with open(&#39;t.dot&#39;, &#39;w&#39;) as file_:<br>X        deferreddump.dump(file_)<br>X<br>
X    first_deferred.unpause()<br>X    if add_final_log:<br>X        deferred.addCallbacks(cb4, twisted.python.log.err)<br>X    else:<br>X        deferred.addCallback(cb4)<br>X<br>X    return deferred<br>X<br>def usage(retval):<br>
X    sys.stderr.write(&#39;Usage: %s --add-final-log\n&#39; % sys.argv[0])<br>X    sys.exit(retval)<br>X<br>def main():<br>X    add_final_log = False<br>X    while sys.argv[1:]:<br>X        if sys.argv[1] == &#39;--add-final-log&#39;:<br>
X            add_final_log = True<br>X        elif sys.argv[1] in [ &#39;-h&#39;, &#39;--help&#39; ]:<br>X            usage(0)<br>X        else:<br>X            sys.stderr.write(&#39;%s: Unrecognized option: %s\n&#39; % (sys.argv[0], sys.argv[1]))<br>
X            usage(1)<br>X        del sys.argv[1]<br>X<br>X    deferred = arbitrary_function(add_final_log)<br>X    with open(&#39;/dev/null&#39;, &#39;w&#39;) as file_:<br>X        file_.write(str(deferred))<br>X<br>X    sys.exit(0)<br>
X<br>main()<br>X<br>SHAR_EOF<br>  (set 20 12 07 02 21 46 02 &#39;wedgedump&#39;<br>   eval &quot;${shar_touch}&quot;) &amp;&amp; \<br>  chmod 0755 &#39;wedgedump&#39;<br>if test $? -ne 0<br>then ${echo} &quot;restore of wedgedump failed&quot;<br>
fi<br>  if ${md5check}<br>  then (<br>       ${MD5SUM} -c &gt;/dev/null 2&gt;&amp;1 || ${echo} &#39;wedgedump&#39;: &#39;MD5 check failed&#39;<br>       ) &lt;&lt; \SHAR_EOF<br>d526664fcf63762f768303af91a74a5f  wedgedump<br>
SHAR_EOF<br>  else<br>test `LC_ALL=C wc -c &lt; &#39;wedgedump&#39;` -ne 3174 &amp;&amp; \<br>  ${echo} &quot;restoration warning:  size of &#39;wedgedump&#39; is not 3174&quot;<br>  fi<br>fi<br>if rm -fr ${lock_dir}<br>then ${echo} &quot;x - removed lock directory ${lock_dir}.&quot;<br>
else ${echo} &quot;x - failed to remove lock directory ${lock_dir}.&quot;<br>     exit 1<br>fi<br>exit 0<br><br>