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

[zooko]

A call to tahoe backup on the command-line ended with this:

uploading './_darcs/patches/0000000452-203b744d7323110202fda6f42296ac24d699e79cfa82df294567276fda24c6ab'..                                                                                          [189/336]
 ./_darcs/patches/0000000452-203b744d7323110202fda6f42296ac24d699e79cfa82df294567276fda24c6ab -> URI:CHK:e2mh2nlllpjxqtihtadu2gdfuq:7274zdu36zq7m65svkkyp3eo3r65oeavmx6dbt7bsikoqwl3lpeq:1:1:332
uploading './_darcs/patches/0000000645-c5799a45bde6fb7b970e7a85b47121dbb72496f4e52ec927dadabb3e0c0ae46c'..
 ./_darcs/patches/0000000645-c5799a45bde6fb7b970e7a85b47121dbb72496f4e52ec927dadabb3e0c0ae46c -> URI:CHK:yzk4twdq36bmeslfb3us27l5zm:5rezjno7rdip2j7ics2w2zpwtylp4wsys55aymyrynplwzx7ztra:1:1:422
uploading './_darcs/patches/0000003657-20949c0699f1e7e939b33ec85764c2565e076988ff8cd51bdfba8b1f24133a15'..
Traceback (most recent call last):
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/runner.py", line 117, in run
    rc = runner(sys.argv[1:], install_node_control=install_node_control)
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/runner.py", line 102, in runner
    rc = cli.dispatch[command](so)
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/cli.py", line 569, in backup
    rc = tahoe_backup.backup(options)
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 325, in backup
    return bu.run()
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 118, in run
    new_backup_dircap = self.process(options.from_dir)
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 188, in process
    childcap = self.process(childpath)
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 188, in process
    childcap = self.process(childpath)
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 194, in process
    childcap, metadata = self.upload(childpath)
  File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/scripts/tahoe_backup.py", line 305, in upload
    raise HTTPError("Error during file PUT", resp)
HTTPError: Error during file PUT: 500 Internal Server Error
"Traceback (most recent call last):\x0a  File \"/home/zooko/playground/tahoe-lafs/dw/src/allmydata/util/pipeline.py\", line 65, in _ebDeferred\x0a    self.checkForFinished()\x0a  File \"/home/zooko/playground/tahoe-lafs/dw/src/allmydata/util/pipeline.py\", line 53, in checkForFinished\x0a    self.errback(self.failure)\x0a  File \"/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 391, in errback\x0a    self._startRunCallbacks(fail)\x0a  File \"/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 458, in _startRunCallbacks\x0a    self._runCallbacks()\x0a--- <exception caught here> ---\x0a  File \"/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 545, in _runCallbacks\x0a    current.result = callback(current.result, *args, **kw)\x0a  File \"/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/encode.py\", line 501, in _remove_shareholder\x0a    raise UploadUnhappinessError(msg)\x0aallmydata.interfaces.UploadUnhappinessError: shares could be placed or found on only 0 server(s). We were asked to place shares on at least 1 server(s) such that any 1 of them have enough shares to recover the file.: [Failure instance: Traceback (failure with no frames): <class 'allmydata.util.pipeline.PipelineError'>: <PipelineError error=([Failure instance: Traceback (failure with no frames): <class 'foolscap.ipb.DeadReferenceError'>: Connection was lost (to tubid=66ra) (during method=RIBucketWriter:write)\x0a])>\x0a]\x0a"

The twistd.log file had:

2012-07-17 08:09:46-0300 [-] 'Original exception:'
2012-07-17 08:09:46-0300 [-] Unhandled Error
        Traceback (most recent call last):
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 287, in addCallbacks
            self._runCallbacks()
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 545, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/upload.py", line 752, in <lambda>
            self._read_encrypted(length, ciphertext, hash_only, d2))
          File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/upload.py", line 767, in _read_encrypted
            d = defer.maybeDeferred(self.original.read, size)
        --- <exception caught here> ---
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 134, in maybeDeferred
            result = f(*args, **kw)
          File "/home/zooko/playground/tahoe-lafs/dw/src/allmydata/immutable/upload.py", line 1467, in read
            return defer.succeed([self._filehandle.read(length)])
        exceptions.ValueError: I/O operation on closed file
        
2012-07-17 08:09:46-0300 [-] Unhandled error in Deferred:
2012-07-17 08:09:46-0300 [-] Unhandled Error
        Traceback (most recent call last):
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/base.py", line 800, in runUntilCurrent
            call.func(*call.args, **call.kw)
          File "/usr/local/lib/python2.7/dist-packages/foolscap-0.6.3.post0-py2.7.egg/foolscap/eventual.py", line 26, in _turn
            cb(*args, **kwargs)
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 362, in callback
            self._startRunCallbacks(result)
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 458, in _startRunCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 545, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Nevow-0.10.0-py2.7.egg/nevow/appserver.py", line 91, in processingFailed
            request.finishRequest( False )
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Nevow-0.10.0-py2.7.egg/nevow/appserver.py", line 176, in finishRequest
            server.Request.finish(self)
          File "/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg/twisted/web/http.py", line 866, in finish
            "Request.finish called on a request after its connection was lost; "
        exceptions.RuntimeError: Request.finish called on a request after its connection was lost; use Request.notifyFinish to keep track of this.
        

The versions are:

$ tahoe --version-and-path
allmydata-tahoe: 1.9.0-r5601 (/home/zooko/playground/tahoe-lafs/dw/src)
foolscap: 0.6.3.post0 (/usr/local/lib/python2.7/dist-packages/foolscap-0.6.3.post0-py2.7.egg)
pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/pycryptopp-0.6.0.1206569328141510525648634803928199668821045408958-py2.7-linux-x86_64.egg)
zfec: 1.4.24 (/usr/local/lib/python2.7/dist-packages/zfec-1.4.24-py2.7-linux-x86_64.egg)
Twisted: 11.1.0 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Twisted-11.1.0-py2.7-linux-x86_64.egg)
Nevow: 0.10.0 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/Nevow-0.10.0-py2.7.egg)
zope.interface: unknown (/usr/local/lib/python2.7/dist-packages/zope.interface-3.6.1-py2.7-linux-x86_64.egg/zope)
python: 2.7.3 (/usr/bin/python)
platform: Linux-Ubuntu_12.04-x86_64-64bit_ELF (None)
pyOpenSSL: 0.12 (/usr/lib/python2.7/dist-packages)
simplejson: 2.3.2 (/usr/lib/python2.7/dist-packages)
pycrypto: 2.5 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/pycrypto-2.5-py2.7-linux-x86_64.egg)
pyasn1: unknown (/usr/lib/python2.7/dist-packages)
mock: 0.8.0beta3 (/usr/local/lib/python2.7/dist-packages)
setuptools: 0.6c16dev3 (/home/zooko/playground/tahoe-lafs/dw/support/lib/python2.7/site-packages/setuptools-0.6c16dev3.egg)

[zooko]

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]

My consulting client (codename "WAG", see comment:6:ticket:1278) has this symptom as well. This is from their storage node's twistd.log:

2014-10-16 19:37:01+0530 [-] Unhandled Error
        Traceback (most recent call last):
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 380, i
n callback
            self._startRunCallbacks(result)
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 488, i
n _startRunCallbacks
            self._runCallbacks()
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 575, i
n _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Nevow-0.11.1-py2.6.egg/nevow/appserver.py", line 163, in gotPageContext
            pageContext.tag.renderHTTP, pageContext
        --- <exception caught here> ---
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 137, i
n maybeDeferred
            result = f(*args, **kw)
          File "/data/allmydata-tahoe-1.10.0/src/allmydata/web/common.py", line 352, in renderHTTP
            return m(ctx)
          File "/data/allmydata-tahoe-1.10.0/src/allmydata/web/filenode.py", line 109, in render_PUT
            return self.replace_me_with_a_child(req, self.client, replace)
          File "/data/allmydata-tahoe-1.10.0/src/allmydata/web/filenode.py", line 32, in replace_me_with_a_child
            data = MutableFileHandle(req.content)
          File "/data/allmydata-tahoe-1.10.0/src/allmydata/mutable/publish.py", line 1219, in __init__
            self._filehandle.seek(0)
        exceptions.ValueError: I/O operation on closed file.
        

I think that this is caused by file descriptor resource exhaustion, because I've seen this in that twistd.log:

2014-11-20 13:33:36+0530 [HTTPChannel,143180,192.168.51.230] Unhandled Error
        Traceback (most recent call last):
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/log.py", line 88, in cal
lWithLogger
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/log.py", line 73, in cal
lWithContext
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/context.py", line 118, i
n callWithContext
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/python/context.py", line 81, in
 callWithContext
            
        --- <exception caught here> ---
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/posixbase.py", line 61
4, in _doReadOrWrite
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/tcp.py", line 215, in 
doRead
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/internet/tcp.py", line 221, in 
_dataReceived
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/protocols/basic.py", line 581, 
in dataReceived
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/web/http.py", line 1609, in lin
eReceived
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/web/http.py", line 1702, in all
HeadersReceived
            
          File "/data/allmydata-tahoe-1.10.0/support/lib/python2.6/site-packages/Twisted-13.0.0-py2.6-linux-x86_64.egg/twisted/web/http.py", line 694, in gotL
ength
            
          File "/usr/lib64/python2.6/tempfile.py", line 475, in TemporaryFile
            
          File "/usr/lib64/python2.6/tempfile.py", line 228, in _mkstemp_inner
            
        exceptions.OSError: [Errno 24] Too many open files: '/GFS2_tahoe/.tahoe-filestore1/tmp/tmpmKDgf6'