Error during POST: 500 Internal Server Error

[killyourtv]

Using tahoe from the 1.9.2 darcs branch on I2P, I received the following copying files to the grid [edited for formatting]:

Error during POST: 500 Internal Server Error
"Traceback (most recent call last):
  File \"/usr/lib/python2.7/dist-packages/twisted/internet/base.py\", line 800, in runUntilCurrent
    call.func(*call.args, **call.kw)
  File \"/usr/lib/pymodules/python2.7/foolscap/eventual.py\", line 26, in _turn
    cb(*args, **kwargs)
  File \"/usr/lib/python2.7/dist-packages/twisted/internet/defer.py\", line 362, in callback
    self._startRunCallbacks(result)
  File \"/usr/lib/python2.7/dist-packages/twisted/internet/defer.py\", line 458, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File \"/usr/lib/python2.7/dist-packages/twisted/internet/defer.py\", line 545, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File \"$HOME/i2p-tahoe/tahoe-lafs-i2p/src/allmydata/mutable/filenode.py\", line 859, in <lambda>
    self._modify_once(modifier, first_time))
  File \"$HOME/i2p-tahoe/tahoe-lafs-i2p/src/allmydata/mutable/filenode.py\", line 885, in _modify_once
    d = self._try_to_download_data()
  File \"$HOME/i2p-tahoe/tahoe-lafs-i2p/src/allmydata/mutable/filenode.py\", line 963, in _try_to_download_data
    d = self._read(c, fetch_privkey=True)
  File \"$HOME/i2p-tahoe/tahoe-lafs-i2p/src/allmydata/mutable/filenode.py\", line 985, in _read
    d = r.download(consumer, offset, size)
  File \"$HOME/i2p-tahoe/tahoe-lafs-i2p/src/allmydata/mutable/retrieve.py\", line 244, in download
    self._setup_download()
  File \"$HOME/i2p-tahoe/tahoe-lafs-i2p/src/allmydata/mutable/retrieve.py\", line 301, in _setup_download
    assert len(self.remaining_sharemap) >= k
exceptions.AssertionError: 
"

allmydata-tahoe: 1.9.0-r5497,
foolscap: 0.6.3,
pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958,
zfec: 1.4.24,
Twisted: 11.1.0,
Nevow: 0.10.0,
zope.interface: unknown,
python: 2.7.3rc2,
platform: Linux-debian_wheezy/sid-x86_64-64bit_ELF,
pyOpenSSL: 0.13,
simplejson: 2.5.2,
pycrypto: 2.5,
pyasn1: unknown,
mock: 0.8.0,
sqlite3: 2.6.0 [sqlite 3.7.11],
setuptools: 0.6c16dev3

[killyourtv]

possibly relevant incident

[killyourtv]

Of course, retrying the put operation completed successfully.

[killyourtv]

The top two operations failed over 12 hours ago

[killyourtv]

In the image below are four "active" operations:

The top two failed around twelve hours earlier but remain in the list.

[killyourtv]

FWIW, I have not seen this with the released v1.9.2---yet.

[zooko]

I just got a report from a customer (TV of Sv) with a matching stack trace, using 1.9.2 [edited for formatting]:

# time tahoe backup TestFiles1M tahoe:Ss1
Traceback (most recent call last):
  File "/root/allmydata-tahoe-1.9.2/support/bin/tahoe", line 9, in <module>
    load_entry_point('allmydata-tahoe==1.9.2', 'console_scripts', 'tahoe')()
  File "/root/allmydata-tahoe-1.9.2/src/allmydata/scripts/runner.py", line 113, in run
    rc = runner(sys.argv[1:], install_node_control=install_node_control)
  File "/root/allmydata-tahoe-1.9.2/src/allmydata/scripts/runner.py", line 99, in runner
    rc = cli.dispatch[command](so)
  File "/root/allmydata-tahoe-1.9.2/src/allmydata/scripts/cli.py", line 569, in backup
    rc = tahoe_backup.backup(options)
  File "/root/allmydata-tahoe-1.9.2/src/allmydata/scripts/tahoe_backup.py", line 325, in backup
    return bu.run()
  File "/root/allmydata-tahoe-1.9.2/src/allmydata/scripts/tahoe_backup.py", line 123, in run
    put_child(archives_url, now, new_backup_dircap)
  File "/root/allmydata-tahoe-1.9.2/src/allmydata/scripts/tahoe_backup.py", line 57, in put_child
    raise HTTPError("Error during put_child", resp)
allmydata.scripts.common_http.HTTPError: Error during put_child: 500 Internal Server Error
"Traceback (most recent call last):
  File \"/root/allmydata-tahoe-1.9.2/support/lib/python2.6/site-packages/Twisted-12.0.0-py2.6-linux-i686.egg/twisted/internet/base.py\", line 800, in runUntilCurrent
    call.func(*call.args, **call.kw)
  File \"/root/allmydata-tahoe-1.9.2/support/lib/python2.6/site-packages/foolscap-0.6.4-py2.6.egg/foolscap/eventual.py\", line 26, in _turn\
    cb(*args, **kwargs)\x0a  File \"/root/allmydata-tahoe-1.9.2/support/lib/python2.6/site-packages/Twisted-12.0.0-py2.6-linux-i686.egg/twisted/internet/defer.py\", line 368, in callback
    self._startRunCallbacks(result)
  File \"/root/allmydata-tahoe-1.9.2/support/lib/python2.6/site-packages/Twisted-12.0.0-py2.6-linux-i686.egg/twisted/internet/defer.py\", line 464, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File \"/root/allmydata-tahoe-1.9.2/support/lib/python2.6/site-packages/Twisted-12.0.0-py2.6-linux-i686.egg/twisted/internet/defer.py\", line 551, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File \"/root/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py\", line 859, in <lambda>
    self._modify_once(modifier, first_time))
  File \"/root/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py\", line 885, in _modify_once
    d = self._try_to_download_data()\x0a  File \"/root/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py\", line 963, in _try_to_download_data
    d = self._read(c, fetch_privkey=True)
  File \"/root/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py\", line 985, in _read
    d = r.download(consumer, offset, size)
  File \"/root/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py\", line 244, in download
    self._setup_download()
  File \"/root/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py\", line 301, in _setup_download
    assert len(self.remaining_sharemap) >= k
exceptions.AssertionError: 
"

[daira]

Similar traceback at ​https://tahoe-lafs.org/pipermail/tahoe-dev/2012-April/007273.html, where it occurred in conjunction with #1670 (but that could be a coincidence).

[zooko]

Tv of Sv carefully and repeatdly confirmed, at my request, that after he gets this exception that the new child does exist in the directory! So this exception is somehow not preventing the directory from being updated!

He wrote:

Yeah, I confirmed it again just now. I took a file already backed up, 100k11, reversed it with tac, saved it a different dir in TestFiles1M as 100k12, did tahoe backup, and got the error message. I did tahoe ls -l and can see 100k12 in the correct location, and can successfully see its contents with tahoe get.

Here's tahoe ls -l after and before:

[root@ls-126 ~]# tahoe ls -l Ss1/Archives/2013-05-07_21:26:17Z
-r-- 104726 May 01 10:26  100k1
-r-- 104433 May 07 14:23 100k12
-r-- 103983 May 01 10:26  100k2
-r-- 104187 May 01 10:26  100k3
-r-- 104850 May 01 10:26  100k4
-r-- 104699 May 03 11:42  100k5
dr-x      - May 01 10:26     d1
dr-x      - May 01 10:26     d2
dr-x      - May 01 10:27     d3
[root@ls-126 ~]# tahoe ls -l Ss1/Archives/2013-05-07_00:28:11Z
-r-- 104726 May 01 10:26 100k1
-r-- 103983 May 01 10:26 100k2
-r-- 104187 May 01 10:26 100k3
-r-- 104850 May 01 10:26 100k4
-r-- 104699 May 03 11:42 100k5
dr-x      - May 01 10:26    d1
dr-x      - May 01 10:26    d2
dr-x      - May 01 10:27    d3