[tahoe-lafs-trac-stream] [tahoe-lafs] #1636: Unhandled error in Deferred while uploading (current darcs build)

[tahoe-lafs]

#1636: Unhandled error in Deferred while uploading (current darcs build)
----------------------------+------------------------
     Reporter:  killyourtv  |      Owner:  zooko
         Type:  defect      |     Status:  assigned
     Priority:  critical    |  Milestone:  1.9.2
    Component:  unknown     |    Version:  1.9.0
   Resolution:              |   Keywords:  regression
Launchpad Bug:              |
----------------------------+------------------------
Changes (by killyourtv):

 * cc: killyourtv@… (added)


Comment:

 Replying to [comment:7 zooko]:

 [...]
 > killyourtv appears to be a reliable reporter of bugs so far -- his
 reports are low on speculation

 [...]


 That was until comment:2 above. :| *Sigh*.

 Anyhow...I'm back testing with was the latest git revision as of a few
 days ago (the webui shows 1.9.0.post77, rev
 2da8339dd762aa96e73b1c1d98e217df43802418).

 {{{
 allmydata-tahoe: 1.9.0.post77,
 foolscap: 0.6.2,
 pycryptopp: 0.5.29,
 zfec: 1.4.22,
 Twisted: 11.1.0,
 Nevow: 0.10.0,
 zope.interface: unknown,
 python: 2.7.2+,
 platform: Linux-debian_wheezy/sid-x86_64-64bit_ELF,
 pyOpenSSL: 0.13,
 simplejson: 2.3.2,
 pycrypto: 2.5,
 pyasn1: unknown,
 mock: 0.7.2,
 sqlite3: 2.6.0 [sqlite 3.7.10],
 setuptools: 0.6c16dev3
 }}}

 Once again, patches from #1007, #1010, and #68 have been applied.
 Everything, so far, seems to be working fine. Or...I should say that
 things are much better than they had been. It's been running for ~36 hours
 now.

 The only problems I've had (a couple error 500s during upload or repair)
 can probably be attributed to our not-always-as-stable-as-we'd-like grid.
 When the failures occurred the tasks remained on the status page, such as

 {{{
 publish         3l6y3gkgdxxwwsn2mwtdmssjse      No      0B      0.0%
 Started
 publish         zyt7tuse472ikqnjc7dmw3ai4y      No      589B    0.0%
 Pushing shares
 }}}

 These entries are from around two hours ago (it currently just after 1am
 UTC). These tasks are no longer running but they're still in the "Active
 Operations" section.

 {{{
     Started: 22:53:57 13-Feb-2012
     Storage Index: 3l6y3gkgdxxwwsn2mwtdmssjse
     Helper?: No
     Current Size: 0
     Progress: 0.0%
     Status: Started

 Retrieve Results

     Encoding: 5 of 10
     Sharemap:
         0 -> Placed on [3t4enhba]
         1 -> Placed on [eyp5vu5v], [bgahn3ft]
         2 -> Placed on [3ejzcskd]
         3 -> Placed on [uxqmbg6c]
         5 -> Placed on [jvgf7m73]
         6 -> Placed on [3teqr2cf], [n64vwepc]
         7 -> Placed on [q5b52rmg]
         8 -> Placed on [ql3cupul], [p6463dyg]
         9 -> Placed on [poeonyl6]
     Timings:
         Total: ()
             Setup:
             Encrypting: 0us ()
             Encoding: 0us ()
             Packing Shares: ()
                 RSA Signature:
             Pushing: ()
 }}}

 {{{
     Started: 23:18:25 13-Feb-2012
     Storage Index: zyt7tuse472ikqnjc7dmw3ai4y
     Helper?: No
     Current Size: 589
     Progress: 0.0%
     Status: Pushing shares

 Retrieve Results

     Encoding: 3 of 10
     Sharemap:
         0 -> Placed on [p6463dyg], [3t4enhba]
         1 -> Placed on [n64vwepc]
         2 -> Placed on [basz6g7o]
         3 -> Placed on [5mefqfis]
         4 -> Placed on [eyp5vu5v]
         5 -> Placed on [3ejzcskd]
         6 -> Placed on [jvgf7m73]
         7 -> Placed on [vvnvgne4]
         8 -> Placed on [iqhk5e2t]
         9 -> Placed on [uxqmbg6c]
     Timings:
         Total: ()
             Setup: 5.7ms
             Encrypting: 283us (2.08MBps)
             Encoding: 151us (3.90MBps)
             Packing Shares: ()
                 RSA Signature: 6.5ms
             Pushing: ()

 }}}



 This is the only entry in twistd.log from around that time:

 {{{
 2012-02-13 23:37:48+0000 [-] Unhandled error in Deferred:
 2012-02-13 23:37:48+0000 [-] Unhandled Error
         Traceback (most recent call last):
           File "/usr/lib/python2.7/dist-packages/nevow/flat/twist.py",
 line 42, in cb
             _drive(iterable, finished)
           File "/usr/lib/python2.7/dist-packages/nevow/flat/twist.py",
 line 26, in _drive
             finished.callback('')
           File "/usr/lib/python2.7/dist-
 packages/twisted/internet/defer.py", line 362, in callback
             self._startRunCallbacks(result)
           File "/usr/lib/python2.7/dist-
 packages/twisted/internet/defer.py", line 458, in _startRunCallbacks
             self._runCallbacks()
         --- <exception caught here> ---
           File "/usr/lib/python2.7/dist-
 packages/twisted/internet/defer.py", line 545, in _runCallbacks
             current.result = callback(current.result, *args, **kw)
           File "/usr/lib/python2.7/dist-packages/nevow/appserver.py", line
 181, in _cbFinishRender
             self.finishRequest(  True )
           File "/usr/lib/python2.7/dist-packages/nevow/appserver.py", line
 176, in finishRequest
             server.Request.finish(self)
           File "/usr/lib/python2.7/dist-packages/twisted/web/http.py",
 line 866, in finish
             "Request.finish called on a request after its connection was
 lost; "
         exceptions.RuntimeError: Request.finish called on a request after
 its connection was lost; use Request.notifyFinish to keep track of this
 }}}

 If I'm around if/when it happens again I'll generate an incident report.

 All that said, things look *much better*.

-- 
Ticket URL: <https://tahoe-lafs.org/trac/tahoe-lafs/ticket/1636#comment:11>
tahoe-lafs <https://tahoe-lafs.org>
secure decentralized storage