upload failed -- "I/O operation on closed file" #1794

New Issue

zooko · 2012-07-17T12:57:00Z

zooko commented

2012-07-17 12:57:00 +00:00

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)

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) ```

zooko added the

labels 2012-07-17 12:57:00 +00:00

zooko added this to the undecided milestone 2012-07-17 12:57:00 +00:00

zooko commented

2012-07-17 13:51:24 +00:00

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:

Pulling from "zooko@tahoe-lafs.org:/home/source/darcs/tahoe-lafs/trunk"...
Sun Jul  1 20:19:21 ADT 2012  david-sarah@jacaranda.org
  * Relnotes, NEWS and quickstart updates for 1.9.2, with updated release date. refs #1776
Shall I pull this patch? (1/4)  [ynW...], or ? for more options: y
Tue Jul  3 11:45:22 ADT 2012  david-sarah@jacaranda.org
  * Slightly improve the error message when a stats.pickle file cannot be read.
Shall I pull this patch? (2/4)  [ynW...], or ? for more options: y
Tue Jul  3 13:30:10 ADT 2012  david-sarah@jacaranda.org
  * Update release date for 1.9.2.
Shall I pull this patch? (3/4)  [ynW...], or ? for more options: y
Thu Jul 12 17:30:26 ADT 2012  david-sarah@jacaranda.org
  * docs/configuration.rst: clarify statement about lack of redundancy when shares.happy <= k. fixes #1793
Shall I pull this patch? (4/4)  [ynW...], or ? for more options: y

$ ./bin/tahoe  --version
allmydata-tahoe: 1.9.0-r5609
foolscap: 0.6.3.post0
pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958
zfec: 1.4.24
Twisted: 11.1.0
Nevow: 0.10.0
zope.interface: unknown
python: 2.7.3
platform: Linux-Ubuntu_12.04-x86_64-64bit_ELF
pyOpenSSL: 0.12
simplejson: 2.3.2
pycrypto: 2.5
pyasn1: unknown
mock: 0.8.0beta3
setuptools: 0.6c16dev3

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: ``` Pulling from "zooko@tahoe-lafs.org:/home/source/darcs/tahoe-lafs/trunk"... Sun Jul 1 20:19:21 ADT 2012 david-sarah@jacaranda.org * Relnotes, NEWS and quickstart updates for 1.9.2, with updated release date. refs #1776 Shall I pull this patch? (1/4) [ynW...], or ? for more options: y Tue Jul 3 11:45:22 ADT 2012 david-sarah@jacaranda.org * Slightly improve the error message when a stats.pickle file cannot be read. Shall I pull this patch? (2/4) [ynW...], or ? for more options: y Tue Jul 3 13:30:10 ADT 2012 david-sarah@jacaranda.org * Update release date for 1.9.2. Shall I pull this patch? (3/4) [ynW...], or ? for more options: y Thu Jul 12 17:30:26 ADT 2012 david-sarah@jacaranda.org * docs/configuration.rst: clarify statement about lack of redundancy when shares.happy <= k. fixes #1793 Shall I pull this patch? (4/4) [ynW...], or ? for more options: y ``` ``` $ ./bin/tahoe --version allmydata-tahoe: 1.9.0-r5609 foolscap: 0.6.3.post0 pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958 zfec: 1.4.24 Twisted: 11.1.0 Nevow: 0.10.0 zope.interface: unknown python: 2.7.3 platform: Linux-Ubuntu_12.04-x86_64-64bit_ELF pyOpenSSL: 0.12 simplejson: 2.3.2 pycrypto: 2.5 pyasn1: unknown mock: 0.8.0beta3 setuptools: 0.6c16dev3 ```

zooko commented

2014-11-28 16:01:57 +00:00

My consulting client (codename "WAG", see comment:81505) 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'

My consulting client (codename "WAG", see [comment:81505](/tahoe-lafs/trac-2024-07-25/issues/1278#issuecomment-81505)) 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' ```

zooko commented

2014-12-18 23:43:32 +00:00

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)

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)

zooko commented

2014-12-19 01:27:14 +00:00

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.

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. ```

zooko commented

2014-12-19 02:09:06 +00:00

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.
 ]

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. ] ```

zooko commented

2014-12-19 04:49:58 +00:00

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!

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](https://github.com/twisted/nevow/blob/master/nevow/static.py#L391). The hypothesis is that Nevow is done producing, but Tahoe-LAFS isn't yet done consuming!

daira commented

2014-12-19 23:18:39 +00:00

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.)

Replying to [zooko](/tahoe-lafs/trac-2024-07-25/issues/1794#issuecomment-89366): > The hypothesis is that Nevow is `close()`'ing the temp file in [stopProducing](https://github.com/twisted/nevow/blob/master/nevow/static.py#L391). 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.)

Sign in to join this conversation.