Opened at 2012-07-17T12:57:00Z
Last modified at 2014-12-19T23:18:39Z
#1794 new defect
upload failed -- "I/O operation on closed file"
| Reported by: | zooko | Owned by: | |
|---|---|---|---|
| Priority: | normal | Milestone: | undecided |
| Component: | code-network | Version: | 1.9.2 |
| Keywords: | upload error twisted | Cc: | |
| Launchpad Bug: |
Description (last modified by zooko)
A call to tahoe backup on the command-line ended with this:
uploading './_darcs/patches/0000000452-203b744d7323110202fda6f42296ac24d699e79cfa82df294567276fda24c6ab'.. [189/336]
./_darcs/patches/0000000452-203b744d7323110202fda6f42296ac24d699e79cfa82df294567276fda24c6ab -> URI:CHK:e2mh2nlllpjxqtihtadu2gdfuq:7274zdu36zq7m65svkkyp3eo3r65oeavmx6dbt7bsikoqwl3lpeq:1:1:332
uploading './_darcs/patches/0000000645-c5799a45bde6fb7b970e7a85b47121dbb72496f4e52ec927dadabb3e0c0ae46c'..
./_darcs/patches/0000000645-c5799a45bde6fb7b970e7a85b47121dbb72496f4e52ec927dadabb3e0c0ae46c -> URI:CHK:yzk4twdq36bmeslfb3us27l5zm:5rezjno7rdip2j7ics2w2zpwtylp4wsys55aymyrynplwzx7ztra:1:1:422
uploading './_darcs/patches/0000003657-20949c0699f1e7e939b33ec85764c2565e076988ff8cd51bdfba8b1f24133a15'..
Traceback (most recent call last):
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/runner.py", line 117, in run
rc = runner(sys.argv[1:], install_node_control=install_node_control)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/runner.py", line 102, in runner
rc = cli.dispatch[command](so)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/cli.py", line 569, in backup
rc = tahoe_backup.backup(options)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 325, in backup
return bu.run()
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 118, in run
new_backup_dircap = self.process(options.from_dir)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 188, in process
childcap = self.process(childpath)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 188, in process
childcap = self.process(childpath)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 194, in process
childcap, metadata = self.upload(childpath)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 305, in upload
raise HTTPError("Error during file PUT", resp)
HTTPError: Error during file PUT: 500 Internal Server Error
"Traceback (most recent call last):\x0a File \"/home/zooko/playground/tahoe-lafs/dw/src/allmydata/util/pipeline.py\", line 65, in _ebDeferred\x0a self.checkForFinished()\x0a File \"/home/zooko/playground/tahoe-lafs/dw/src/allmydata/util/pipeline.py\", line 53, in checkForFinished\x0a self.errback(self.failure)\x0a File \"/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 391, in errback\x0a self._startRunCallbacks(fail)\x0a File \"/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 458, in _startRunCallbacks\x0a self._runCallbacks()\x0a--- <exception caught here> ---\x0a File \"/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 545, in _runCallbacks\x0a current.result = callback(current.result, *args, **kw)\x0a File \"/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/encode.py\", line 501, in _remove_shareholder\x0a raise UploadUnhappinessError(msg)\x0aallmydata.interfaces.UploadUnhappinessError: shares could be placed or found on only 0 server(s). We were asked to place shares on at least 1 server(s) such that any 1 of them have enough shares to recover the file.: [Failure instance: Traceback (failure with no frames): <class 'allmydata.util.pipeline.PipelineError'>: <PipelineError error=([Failure instance: Traceback (failure with no frames): <class 'foolscap.ipb.DeadReferenceError'>: Connection was lost (to tubid=66ra) (during method=RIBucketWriter:write)\x0a])>\x0a]\x0a"
The twistd.log file had:
2012-07-17 08:09:46-0300 [-] 'Original exception:'
2012-07-17 08:09:46-0300 [-] Unhandled Error
Traceback (most recent call last):
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 287, in addCallbacks
self._runCallbacks()
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 545, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/upload.py", line 752, in <lambda>
self._read_encrypted(length, ciphertext, hash_only, d2))
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/upload.py", line 767, in _read_encrypted
d = defer.maybeDeferred(self.original.read, size)
--- <exception caught here> ---
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 134, in maybeDeferred
result = f(*args, **kw)
File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/upload.py", line 1467, in read
return defer.succeed([self._filehandle.read(length)])
exceptions.ValueError: I/O operation on closed file
2012-07-17 08:09:46-0300 [-] Unhandled error in Deferred:
2012-07-17 08:09:46-0300 [-] Unhandled Error
Traceback (most recent call last):
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/base.py", line 800, in runUntilCurrent
call.func(*call.args, **call.kw)
File "/usr/local/lib/python2.7/dist-packages/foolscap-0.6.3.post0-py2.7.egg/foolscap/eventual.py", line 26, in _turn
cb(*args, **kwargs)
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 362, in callback
self._startRunCallbacks(result)
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 458, in _startRunCallbacks
self._runCallbacks()
--- <exception caught here> ---
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 545, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Nevow-0.10.0-py2.7.egg/nevow/appserver.py", line 91, in processingFailed
request.finishRequest( False )
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Nevow-0.10.0-py2.7.egg/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/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.
The versions are:
$ tahoe --version-and-path allmydata-tahoe: 1.9.0-r5601 (/home/zooko/playground/tahoe-lafs/dw/src) foolscap: 0.6.3.post0 (/usr/local/lib/python2.7/dist-packages/foolscap-0.6.3.post0-py2.7.egg) pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/pycryptopp-0.6.0.1206569328141510525648634803928199668821045408958-py2.7-linux-x86_64.egg) zfec: 1.4.24 (/usr/local/lib/python2.7/dist-packages/zfec-1.4.24-py2.7-linux-x86_64.egg) Twisted: 11.1.0 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg) Nevow: 0.10.0 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Nevow-0.10.0-py2.7.egg) zope.interface: unknown (/usr/local/lib/python2.7/dist-packages/zope.interface-3.6.1-py2.7-linux-x86_64.egg/zope) python: 2.7.3 (/usr/bin/python) platform: Linux-Ubuntu_12.04-x86_64-64bit_ELF (None) pyOpenSSL: 0.12 (/usr/lib/python2.7/dist-packages) simplejson: 2.3.2 (/usr/lib/python2.7/dist-packages) pycrypto: 2.5 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/pycrypto-2.5-py2.7-linux-x86_64.egg) pyasn1: unknown (/usr/lib/python2.7/dist-packages) mock: 0.8.0beta3 (/usr/local/lib/python2.7/dist-packages) setuptools: 0.6c16dev3 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/setuptools-0.6c16dev3.egg)
Change History (8)
comment:1 Changed at 2012-07-17T13:51:24Z by zooko
comment:2 Changed at 2012-11-22T01:29:47Z by davidsarah
- Keywords error twisted added
comment:3 Changed at 2014-11-28T16:01:57Z by zooko
- Description modified (diff)
My consulting client (codename "WAG", see comment:6:ticket:1278) has this symptom as well. This is from their storage node's twistd.log:
2014-10-16 19:37:01+0530 [-] Unhandled Error
Traceback (most recent call last):
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 380, i
n callback
self._startRunCallbacks(result)
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 488, i
n _startRunCallbacks
self._runCallbacks()
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 575, i
n _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Nevow-0.11.1-py2.6.egg/nevow/appserver.py", line 163, in gotPageContext
pageContext.tag.renderHTTP, pageContext
--- <exception caught here> ---
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 137, i
n maybeDeferred
result = f(*args, **kw)
File "/data/allmydata-tahoe-1.10.0/src/allmydata/web/common.py", line 352, in renderHTTP
return m(ctx)
File "/data/allmydata-tahoe-1.10.0/src/allmydata/web/filenode.py", line 109, in render_PUT
return self.replace_me_with_a_child(req, self.client, replace)
File "/data/allmydata-tahoe-1.10.0/src/allmydata/web/filenode.py", line 32, in replace_me_with_a_child
data = MutableFileHandle(req.content)
File "/data/allmydata-tahoe-1.10.0/src/allmydata/mutable/publish.py", line 1219, in __init__
self._filehandle.seek(0)
exceptions.ValueError: I/O operation on closed file.
I think that this is caused by file descriptor resource exhaustion, because I've seen this in that twistd.log:
2014-11-20 13:33:36+0530 [HTTPChannel,143180,192.168.51.230] Unhandled Error
Traceback (most recent call last):
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/log.py", line 88, in cal
lWithLogger
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/log.py", line 73, in cal
lWithContext
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/context.py", line 118, i
n callWithContext
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/context.py", line 81, in
callWithContext
--- <exception caught here> ---
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/posixbase.py", line 61
4, in _doReadOrWrite
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/tcp.py", line 215, in
doRead
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/tcp.py", line 221, in
_dataReceived
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/protocols/basic.py", line 581,
in dataReceived
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/web/http.py", line 1609, in lin
eReceived
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/web/http.py", line 1702, in all
HeadersReceived
File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/web/http.py", line 694, in gotL
ength
File "/usr/lib64/python2.6/tempfile.py", line 475, in TemporaryFile
File "/usr/lib64/python2.6/tempfile.py", line 228, in _mkstemp_inner
exceptions.OSError: [Errno 24] Too many open files: '/GFS2_tahoe/.tahoe-filestore1/tmp/tmpmKDgf6'
comment:4 Changed at 2014-12-18T23:43:32Z by zooko
A customer (now former customer) of LeastAuthority's S4 service, named AB, reported a problem, and his twistd.log contains this:
2014-11-08 17:46:18+0000 [SSHService ssh-connection on SSHServerTransport,1,127.0.0.1] adding 81920 to 49152 in channel 0
2014-11-08 17:46:18+0000 [SSHService ssh-connection on SSHServerTransport,1,127.0.0.1] adding 81920 to 49152 in channel 0
2014-11-08 17:46:18+0000 [SSHService ssh-connection on SSHServerTransport,1,127.0.0.1] adding 81920 to 49152 in channel 0
2014-11-08 17:46:37+0000 [-] Unhandled error in Deferred:
2014-11-08 17:46:37+0000 [-] Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/nevow/flat/twist.py", line 42, in cb
_drive(iterable, finished)
File "/usr/lib64/python2.7/site-packages/nevow/flat/twist.py", line 26, in _drive
finished.callback('')
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 181, in _cbFinishRender
self.finishRequest( True )
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
2014-11-08 17:50:08+0000 [SSHServerTransport,1,127.0.0.1] Got remote error, code 11
reason: disconnected by user
2014-11-08 17:50:08+0000 [SSHServerTransport,1,127.0.0.1] connection lost
2014-11-08 17:52:10+0000 [-] Log opened.
2014-11-08 17:52:10+0000 [-] twistd 14.0.0 (/usr/bin/python2.7 2.7.8) starting up.
2014-11-08 17:52:10+0000 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2014-11-08 17:52:10+0000 [-] Listener starting on 51077
2014-11-08 17:52:10+0000 [-] SSHFactory starting on 8022
2014-11-08 17:52:10+0000 [-] Starting factory <allmydata.frontends.sftpd.SSHFactory instance at 0x7f9451502e18>
2014-11-08 17:52:10+0000 [-] NevowSite starting on 3456
2014-11-08 17:52:10+0000 [-] Starting factory <nevow.appserver.NevowSite instance at 0x7f94510b4488>
2014-11-08 17:52:10+0000 [-] My pid: 16255
2014-11-08 17:52:10+0000 [-] DatagramProtocol starting on 47997
2014-11-08 17:52:10+0000 [-] Starting protocol <twisted.internet.protocol.DatagramProtocol instance at 0x7f9450c6ddd0>
2014-11-08 17:52:10+0000 [-] (UDP Port 47997 Closed)
2014-11-08 17:52:10+0000 [-] Stopping protocol <twisted.internet.protocol.DatagramProtocol instance at 0x7f9450c6ddd0>
2014-11-08 17:53:30+0000 [-] Exception rendering error page:
2014-11-08 17:53:30+0000 [-] Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn
cb(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 82, in processingFailed
handler.renderHTTP_exception(ctx, reason)
File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 332, in renderHTTP_exception
return self.simple(ctx, traceback, http.INTERNAL_SERVER_ERROR)
File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 302, in simple
req.finishRequest(False)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
2014-11-08 17:53:30+0000 [-] 'Original exception:'
2014-11-08 17:53:30+0000 [-] Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
self._runCallbacks()
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 752, in <lambda>
self._read_encrypted(length, ciphertext, hash_only, d2))
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 767, in _read_encrypted
d = defer.maybeDeferred(self.original.read, size)
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 139, in maybeDeferred
result = f(*args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 1467, in read
return defer.succeed([self._filehandle.read(length)])
exceptions.ValueError: I/O operation on closed file
2014-11-08 17:53:30+0000 [-] Unhandled error in Deferred:
2014-11-08 17:53:30+0000 [-] Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 824, in runUntilCurrent
call.func(*call.args, **call.kw)
File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn
cb(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 91, in processingFailed
request.finishRequest( False )
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
2014-11-08 17:53:57+0000 [-] Unhandled error in Deferred:
2014-11-08 17:53:57+0000 [-] Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 169, in gotPageContext
self._cbFinishRender, pageContext
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 306, in addCallback
callbackKeywords=kw)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
self._runCallbacks()
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 181, in _cbFinishRender
self.finishRequest( True )
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
2014-11-08 17:54:28+0000 [-] Unhandled error in Deferred:
2014-11-08 17:54:28+0000 [-] Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/nevow/flat/twist.py", line 42, in cb
_drive(iterable, finished)
File "/usr/lib64/python2.7/site-packages/nevow/flat/twist.py", line 26, in _drive
finished.callback('')
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 181, in _cbFinishRender
self.finishRequest( True )
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
(plus much more of the same)
comment:5 Changed at 2014-12-19T01:27:14Z by zooko
Erstwhile customer AB reports this result from lsof:
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME tahoe 17548 root cwd DIR 0,17 196 7835586 /root/.tahoe tahoe 17548 root rtd DIR 0,17 792 256 / tahoe 17548 root txt REG 0,17 6160 7145804 /usr/bin/python2.7 tahoe 17548 root mem REG 0,15 7145804 /usr/bin/python2.7 (path dev=0,17) tahoe 17548 root mem REG 0,15 2324166 /usr/lib64/libexpat.so.1.6.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 7145964 /usr/lib64/python2.7/lib-dynload/pyexpat.so (path dev=0,17) tahoe 17548 root mem REG 0,15 5586190 /lib64/libnss_ldap-2.19.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9100932 /lib64/libnss_dns-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9514490 /usr/lib64/libgpg-error.so.0.13.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180104 /usr/lib64/samba/libflag_mapping.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9253323 /usr/lib64/libhogweed.so.2.5 (path dev=0,17) tahoe 17548 root mem REG 0,15 9253322 /usr/lib64/libnettle.so.4.7 (path dev=0,17) tahoe 17548 root mem REG 0,15 3318025 /usr/lib64/libtasn1.so.6.3.2 (path dev=0,17) tahoe 17548 root mem REG 0,15 1433815 /usr/lib64/libheimntlm.so.0.1.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 9100703 /lib64/libcrypt-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 1434113 /usr/lib64/libroken.so.18.1.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 1433812 /usr/lib64/libhcrypto.so.4.1.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 9250241 /usr/lib64/libsqlite3.so.0.8.6 (path dev=0,17) tahoe 17548 root mem REG 0,15 1434239 /usr/lib64/libwind.so.0.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 1433822 /usr/lib64/libhx509.so.5.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 1433814 /usr/lib64/libheimbase.so.1.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 3341999 /usr/lib64/libgcrypt.so.20.0.2 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180112 /usr/lib64/samba/libauth_sam_reply.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180092 /usr/lib64/libndr-krb5pac.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180113 /usr/lib64/samba/libldbsamba.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180106 /usr/lib64/samba/libsamdb-common.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180120 /usr/lib64/libsamdb.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180091 /usr/lib64/samba/libndr-samba.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180119 /usr/lib64/samba/libsamba-modules.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180111 /usr/lib64/samba/libcliauth.so (path dev=0,17) tahoe 17548 root mem REG 0,15 1433478 /usr/lib64/libasn1.so.8.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 9823998 /usr/lib64/libldb.so.1.1.18 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180098 /usr/lib64/samba/libasn1util.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180107 /usr/lib64/samba/libcli-ldap-common.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9571157 /usr/lib64/libgnutls.so.28.41.2 (path dev=0,17) tahoe 17548 root mem REG 0,15 3386138 /usr/lib64/libsasl2.so.3.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 9100934 /lib64/libresolv-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 3093872 /lib64/libattr.so.1.1.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180096 /usr/lib64/libndr-nbt.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 9637656 /usr/lib64/libntdb.so.1.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180108 /usr/lib64/samba/libutil_ntdb.so (path dev=0,17) tahoe 17548 root mem REG 0,15 3378309 /lib64/libcom_err.so.2.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 1433737 /usr/lib64/libgssapi.so.3.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 1433897 /usr/lib64/libkrb5.so.26.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180094 /usr/lib64/samba/libcli-nbt.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180115 /usr/lib64/samba/libauthkrb5.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180103 /usr/lib64/libsamba-credentials.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180117 /usr/lib64/libgensec.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180186 /usr/lib64/samba/libsecrets3.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180109 /usr/lib64/samba/libkrb5samba.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180128 /usr/lib64/samba/libcli_cldap.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180083 /usr/lib64/samba/libaddns.so (path dev=0,17) tahoe 17548 root mem REG 0,15 6249370 /usr/lib64/libldap-2.4.so.2.10.3 (path dev=0,17) tahoe 17548 root mem REG 0,15 9629470 /usr/lib64/libtdb.so.1.3.3 (path dev=0,17) tahoe 17548 root mem REG 0,15 6249372 /usr/lib64/liblber-2.4.so.2.10.3 (path dev=0,17) tahoe 17548 root mem REG 0,15 3154798 /lib64/libcap.so.2.22 (path dev=0,17) tahoe 17548 root mem REG 0,15 9101141 /lib64/libnsl-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180101 /usr/lib64/libndr-standard.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180084 /usr/lib64/samba/libserver-role.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180090 /usr/lib64/libsamba-hostconfig.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180118 /usr/lib64/samba/libsmb_transport.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180085 /usr/lib64/samba/libtdb-wrap.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180082 /usr/lib64/samba/libutil_setid.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180199 /usr/lib64/samba/libsmbd_shim.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180095 /usr/lib64/samba/libsamba-security.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180099 /usr/lib64/samba/libsamba-sockets.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180194 /usr/lib64/samba/libutil_reg.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180197 /usr/lib64/samba/libsamba3-util.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180116 /usr/lib64/samba/libcli_smb_common.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180087 /usr/lib64/libndr.so.0.0.2 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180114 /usr/lib64/samba/libutil_tdb.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180080 /usr/lib64/samba/liberrors.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180192 /usr/lib64/samba/libCHARSET3.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180110 /usr/lib64/samba/libdbwrap.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180079 /usr/lib64/samba/libccan.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180097 /usr/lib64/libtevent-util.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180078 /usr/lib64/samba/libinterfaces.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180193 /usr/lib64/samba/libsmbregistry.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9621400 /usr/lib64/libtevent.so.0.9.22 (path dev=0,17) tahoe 17548 root mem REG 0,15 9100737 /lib64/librt-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9584083 /usr/lib64/libtalloc.so.2.1.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180271 /usr/lib64/samba/libgse.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180191 /usr/lib64/libsmbconf.so.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180077 /usr/lib64/samba/libreplace.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10180081 /usr/lib64/libsamba-util.so.0.0.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 10180313 /usr/lib64/libnss_wins.so.2 (path dev=0,17) tahoe 17548 root mem REG 0,15 9100990 /lib64/libnss_files-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9454529 /usr/lib64/python2.7/site-packages/Crypto/Util/_counter.so (path dev=0,17) tahoe 17548 root mem REG 0,15 2409990 /usr/lib64/libgmp.so.10.2.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 9454528 /usr/lib64/python2.7/site-packages/Crypto/PublicKey/_fastmath.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9454518 /usr/lib64/python2.7/site-packages/Crypto/Cipher/_AES.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145956 /usr/lib64/python2.7/lib-dynload/resource.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145940 /usr/lib64/python2.7/lib-dynload/syslog.so (path dev=0,17) tahoe 17548 root mem REG 0,15 2321727 /lib64/libbz2.so.1.0.6 (path dev=0,17) tahoe 17548 root mem REG 0,15 7145963 /usr/lib64/python2.7/lib-dynload/bz2.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145872 /usr/lib64/python2.7/lib-dynload/_bisect.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9484347 /usr/lib64/python2.7/site-packages/simplejson/_speedups.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145816 /usr/lib64/python2.7/lib-dynload/array.so (path dev=0,17) tahoe 17548 root mem REG 0,15 6895662 /usr/lib64/python2.7/site-packages/zfec/_fec.so (path dev=0,17) tahoe 17548 root mem REG 0,15 6894822 /usr/lib64/python2.7/site-packages/pycryptopp/publickey/ed25519/_ed25519.so (path dev=0,17) tahoe 17548 root mem REG 0,15 4650844 /usr/lib64/gcc/x86_64-pc-linux-gnu/4.8.3/libgcc_s.so.1 (path dev=0,17) tahoe 17548 root mem REG 0,15 4651118 /usr/lib64/gcc/x86_64-pc-linux-gnu/4.8.3/libstdc++.so.6.0.19 (path dev=0,17) tahoe 17548 root mem REG 0,15 6892940 /usr/lib64/libcrypto++.so.0.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 6894823 /usr/lib64/python2.7/site-packages/pycryptopp/_pycryptopp.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145937 /usr/lib64/python2.7/lib-dynload/cPickle.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145942 /usr/lib64/python2.7/lib-dynload/_csv.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145925 /usr/lib64/python2.7/lib-dynload/_json.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145928 /usr/lib64/python2.7/lib-dynload/unicodedata.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145952 /usr/lib64/python2.7/lib-dynload/termios.so (path dev=0,17) tahoe 17548 root mem REG 0,15 2859901 /usr/lib64/python2.7/site-packages/cryptography/_Cryptography_cffi_36a40ff0x2bad1bae.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9454526 /usr/lib64/python2.7/site-packages/Crypto/Cipher/_DES3.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9552920 /usr/lib64/python2.7/site-packages/_cffi_backend.so (path dev=0,17) tahoe 17548 root mem REG 0,15 2344194 /usr/lib64/libffi.so.6.0.2 (path dev=0,17) tahoe 17548 root mem REG 0,15 7145976 /usr/lib64/python2.7/lib-dynload/_ctypes.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9465422 /usr/lib64/python2.7/site-packages/zope/interface/_zope_interface_coptimizations.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145936 /usr/lib64/python2.7/lib-dynload/select.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145932 /usr/lib64/python2.7/lib-dynload/parser.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145931 /usr/lib64/python2.7/lib-dynload/fcntl.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145934 /usr/lib64/python2.7/lib-dynload/_locale.so (path dev=0,17) tahoe 17548 root mem REG 0,15 2756485 /usr/lib64/libssl.so.1.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 7145945 /usr/lib64/python2.7/lib-dynload/_ssl.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145947 /usr/lib64/python2.7/lib-dynload/_socket.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145845 /usr/lib64/python2.7/lib-dynload/_random.so (path dev=0,17) tahoe 17548 root mem REG 0,15 2756484 /usr/lib64/libcrypto.so.1.0.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 7145946 /usr/lib64/python2.7/lib-dynload/_hashlib.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145835 /usr/lib64/python2.7/lib-dynload/math.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145840 /usr/lib64/python2.7/lib-dynload/datetime.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145926 /usr/lib64/python2.7/lib-dynload/_functools.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145959 /usr/lib64/python2.7/lib-dynload/zlib.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145832 /usr/lib64/python2.7/lib-dynload/strop.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145938 /usr/lib64/python2.7/lib-dynload/cStringIO.so (path dev=0,17) tahoe 17548 root mem REG 0,15 2658860 /lib64/libz.so.1.2.8 (path dev=0,17) tahoe 17548 root mem REG 0,15 7145962 /usr/lib64/python2.7/lib-dynload/binascii.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145933 /usr/lib64/python2.7/lib-dynload/grp.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145870 /usr/lib64/python2.7/lib-dynload/_heapq.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145838 /usr/lib64/python2.7/lib-dynload/itertools.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145883 /usr/lib64/python2.7/lib-dynload/operator.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145863 /usr/lib64/python2.7/lib-dynload/_collections.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145811 /usr/lib64/python2.7/lib-dynload/_struct.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145833 /usr/lib64/python2.7/lib-dynload/time.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7145884 /usr/lib64/python2.7/lib-dynload/_io.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9103048 /usr/lib64/locale/locale-archive (path dev=0,17) tahoe 17548 root mem REG 0,15 9100632 /lib64/libm-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9101238 /lib64/libutil-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9100630 /lib64/libdl-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9101312 /lib64/libc-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 9102815 /lib64/libpthread-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 7141028 /usr/lib64/libpython2.7.so.1.0 (path dev=0,17) tahoe 17548 root mem REG 0,15 9101310 /lib64/ld-2.20.so (path dev=0,17) tahoe 17548 root mem REG 0,15 10179068 /usr/share/samba/codepages/lowcase.dat (path dev=0,17) tahoe 17548 root mem REG 0,15 10179069 /usr/share/samba/codepages/upcase.dat (path dev=0,17) tahoe 17548 root 0u CHR 1,3 0t0 8 /dev/null tahoe 17548 root 1u CHR 1,3 0t0 8 /dev/null tahoe 17548 root 2u CHR 1,3 0t0 8 /dev/null tahoe 17548 root 3u REG 0,17 47363 8357894 /root/.tahoe/logs/twistd.log tahoe 17548 root 4r CHR 1,9 0t0 13 /dev/urandom tahoe 17548 root 5r FIFO 0,7 0t0 1009081 pipe tahoe 17548 root 6r FIFO 0,7 0t0 1008144 pipe tahoe 17548 root 7u IPv4 1009082 0t0 TCP *:51077 (LISTEN) tahoe 17548 root 8u IPv4 1009083 0t0 TCP localhost:8022 (LISTEN) tahoe 17548 root 9u a_inode 0,8 0 4 [eventpoll] tahoe 17548 root 10r FIFO 0,7 0t0 1006713 pipe tahoe 17548 root 11w FIFO 0,7 0t0 1006713 pipe tahoe 17548 root 12u IPv4 1008143 0t0 TCP localhost:3456 (LISTEN) tahoe 17548 root 13w FIFO 0,7 0t0 1008144 pipe tahoe 17548 root 14u IPv4 1007115 0t0 TCP 192.168.8.1:60535->ec2-54-174-161-75.compute-1.amazonaws.com:12345 (ESTABLISHED) tahoe 17548 root 15u IPv4 1055689 0t0 TCP localhost:3456->localhost:51674 (ESTABLISHED) tahoe 17548 root 16u IPv4 1007119 0t0 TCP 192.168.8.1:58407->ec2-54-174-161-75.compute-1.amazonaws.com:12346 (ESTABLISHED) tahoe 17548 root 17r CHR 1,9 0t0 13 /dev/urandom tahoe 17548 root 18u IPv4 1008169 0t0 TCP undercity:34288->undercity:ldap (ESTABLISHED) tahoe 17548 root 19r CHR 1,9 0t0 13 /dev/urandom tahoe 17548 root 20u REG 0,17 475389401 11584559 /root/.tahoe/tmp/tmp0Is820 (deleted)
with this twistd.log:
2014-12-19 00:43:02+0000 [-] Log opened. 2014-12-19 00:43:02+0000 [-] twistd 14.0.2 (/usr/bin/python2.7 2.7.8) starting up. 2014-12-19 00:43:02+0000 [-] reactor class: twisted.internet.epollreactor.EPollReactor. 2014-12-19 00:43:02+0000 [-] Listener starting on 51077 2014-12-19 00:43:02+0000 [-] SSHFactory starting on 8022 2014-12-19 00:43:02+0000 [-] Starting factory <allmydata.frontends.sftpd.SSHFactory instance at 0x7f2fee40fe60> 2014-12-19 00:43:02+0000 [-] NevowSite starting on 3456 2014-12-19 00:43:02+0000 [-] Starting factory <nevow.appserver.NevowSite instance at 0x7f2fedfc1440> 2014-12-19 00:43:02+0000 [-] My pid: 17548 2014-12-19 00:43:02+0000 [-] DatagramProtocol starting on 44901 2014-12-19 00:43:02+0000 [-] Starting protocol <twisted.internet.protocol.DatagramProtocol instance at 0x7f2fedb7ad88> 2014-12-19 00:43:02+0000 [-] (UDP Port 44901 Closed) 2014-12-19 00:43:02+0000 [-] Stopping protocol <twisted.internet.protocol.DatagramProtocol instance at 0x7f2fedb7ad88> 2014-12-19 00:59:39+0000 [-] Exception rendering error page: 2014-12-19 00:59:39+0000 [-] Unhandled Error Traceback (most recent call last): File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn cb(*args, **kwargs) File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback self._startRunCallbacks(result) File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks self._runCallbacks() File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks current.result = callback(current.result, *args, **kw) --- <exception caught here> --- File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 82, in processingFailed handler.renderHTTP_exception(ctx, reason) File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 332, in renderHTTP_exception return self.simple(ctx, traceback, http.INTERNAL_SERVER_ERROR) File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 302, in simple req.finishRequest(False) File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest server.Request.finish(self) File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish return http.Request.finish(self) File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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. 2014-12-19 00:59:39+0000 [-] 'Original exception:' 2014-12-19 00:59:39+0000 [-] Unhandled Error Traceback (most recent call last): File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks self._runCallbacks() File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks current.result = callback(current.result, *args, **kw) File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 752, in <lambda> self._read_encrypted(length, ciphertext, hash_only, d2)) File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 767, in _read_encrypted d = defer.maybeDeferred(self.original.read, size) --- <exception caught here> --- File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 139, in maybeDeferred result = f(*args, **kw) File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 1467, in read return defer.succeed([self._filehandle.read(length)]) exceptions.ValueError: I/O operation on closed file 2014-12-19 00:59:39+0000 [-] Unhandled error in Deferred: 2014-12-19 00:59:39+0000 [-] Unhandled Error Traceback (most recent call last): File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 824, in runUntilCurrent call.func(*call.args, **call.kw) File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn cb(*args, **kwargs) File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback self._startRunCallbacks(result) File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks self._runCallbacks() --- <exception caught here> --- File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks current.result = callback(current.result, *args, **kw) File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 91, in processingFailed request.finishRequest( False ) File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest server.Request.finish(self) File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish return http.Request.finish(self) File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
comment:6 Changed at 2014-12-19T02:09:06Z by zooko
AB pressed the Report An Incident button, and mailed me the resulting incident report file. I'll attach it to this ticket, but here is the first evidence of weirdness in it:
local#12548 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.491843Z): upload failed
FAILURE:
[CopiedFailure instance: Traceback from remote host -- Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
self._runCallbacks()
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 752, in <lambda>
self._read_encrypted(length, ciphertext, hash_only, d2))
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 767, in _read_encrypted
d = defer.maybeDeferred(self.original.read, size)
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 139, in maybeDeferred
result = f(*args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 1467, in read
return defer.succeed([self._filehandle.read(length)])
exceptions.ValueError: I/O operation on closed file
]
local#12549 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.608912Z): aborting shareholders
local#12550 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.618792Z): Exception rendering error page:
local#12551 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.646960Z): Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn
cb(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 82, in processingFailed
handler.renderHTTP_exception(ctx, reason)
File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 332, in renderHTTP_exception
return self.simple(ctx, traceback, http.INTERNAL_SERVER_ERROR)
File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 302, in simple
req.finishRequest(False)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
FAILURE:
[CopiedFailure instance: Traceback from remote host -- Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn
cb(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 82, in processingFailed
handler.renderHTTP_exception(ctx, reason)
File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 332, in renderHTTP_exception
return self.simple(ctx, traceback, http.INTERNAL_SERVER_ERROR)
File "/usr/lib64/python2.7/site-packages/allmydata/web/common.py", line 302, in simple
req.finishRequest(False)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
]
local#12552 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.852801Z): 'Original exception:'
local#12553 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.853193Z): Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
self._runCallbacks()
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 752, in <lambda>
self._read_encrypted(length, ciphertext, hash_only, d2))
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 767, in _read_encrypted
d = defer.maybeDeferred(self.original.read, size)
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 139, in maybeDeferred
result = f(*args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 1467, in read
return defer.succeed([self._filehandle.read(length)])
exceptions.ValueError: I/O operation on closed file
FAILURE:
[CopiedFailure instance: Traceback from remote host -- Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
self._runCallbacks()
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 752, in <lambda>
self._read_encrypted(length, ciphertext, hash_only, d2))
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 767, in _read_encrypted
d = defer.maybeDeferred(self.original.read, size)
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 139, in maybeDeferred
result = f(*args, **kw)
File "/usr/lib64/python2.7/site-packages/allmydata/immutable/upload.py", line 1467, in read
return defer.succeed([self._filehandle.read(length)])
exceptions.ValueError: I/O operation on closed file
]
local#12554 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.855494Z): Unhandled error in Deferred:
local#12555 rx(2014-12-19_01:06:25.269490Z) emit(2014-12-19_00:59:39.855931Z): Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 824, in runUntilCurrent
call.func(*call.args, **call.kw)
File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn
cb(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 91, in processingFailed
request.finishRequest( False )
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
FAILURE:
[CopiedFailure instance: Traceback from remote host -- Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 824, in runUntilCurrent
call.func(*call.args, **call.kw)
File "/usr/lib64/python2.7/site-packages/foolscap/eventual.py", line 26, in _turn
cb(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 91, in processingFailed
request.finishRequest( False )
File "/usr/lib64/python2.7/site-packages/nevow/appserver.py", line 176, in finishRequest
server.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/server.py", line 228, in finish
return http.Request.finish(self)
File "/usr/lib64/python2.7/site-packages/twisted/web/http.py", line 930, 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.
]
comment:7 follow-up: ↓ 8 Changed at 2014-12-19T04:49:58Z by zooko
Okay here's a hypothesis. I need someone to verify this for me — warner, daira, dreid, ??
The hypothesis is that Nevow is close()'ing the temp file in stopProducing. The hypothesis is that Nevow is done producing, but Tahoe-LAFS isn't yet done consuming!
comment:8 in reply to: ↑ 7 Changed at 2014-12-19T23:18:39Z by daira
Replying to zooko:
The hypothesis is that Nevow is close()'ing the temp file in stopProducing. The hypothesis is that Nevow is done producing, but Tahoe-LAFS isn't yet done consuming!
That seems plausible to me. To test it, we should instrument Nevow to log when it is closing the temp file; if this log entry comes just before the "I/O operation on closed file", then we've confirmed the hypothesis.
It also seems plausible that we can work around this by os.dup'ing the file handle when we get it (in render_{PUT,POST}), and closing our duplicate when we are finished. (I am assuming that Nevow cannot already have closed the file when we first get it; that would be a Nevow bug that we can't fix.)
Note: See
TracTickets for help on using
tickets.
I did a darcs pull and got only a few minor patches, so the version that exhibited this error is almost identical to 1.9.2 release: