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

[zooko]

At my request, Tv of Sv reproduced it with Tahoe-LAFS v1.10.0 gateway:

Traceback (most recent call last):
  File "/home/sv1/.local/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 "/home/sv1/.local/lib/python2.6/site-packages/foolscap-0.6.4-py2.6.egg/foolscap/eventual.py", line 26, in _turn
    cb(*args, **kwargs)
  File "/home/sv1/.local/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 "/home/sv1/.local/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 "/home/sv1/.local/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.10.0/src/allmydata/mutable/filenode.py", line 854, in <lambda>
    self._modify_once(modifier, first_time))
  File "/root/allmydata-tahoe-1.10.0/src/allmydata/mutable/filenode.py", line 880, in _modify_once
    d = self._try_to_download_data()
  File "/root/allmydata-tahoe-1.10.0/src/allmydata/mutable/filenode.py", line 958, in _try_to_download_data
    d = self._read(c, fetch_privkey=True)
  File "/root/allmydata-tahoe-1.10.0/src/allmydata/mutable/filenode.py", line 980, in _read
    d = r.download(consumer, offset, size)
  File "/root/allmydata-tahoe-1.10.0/src/allmydata/mutable/retrieve.py", line 244, in download
    self._setup_download()
  File "/root/allmydata-tahoe-1.10.0/src/allmydata/mutable/retrieve.py", line 299, in _setup_download
    assert len(self.remaining_sharemap) >= k
exceptions.AssertionError: 

[daira]

Work in progress at ​https://github.com/daira/tahoe-lafs/commits/1742-error-during-post.

[Daira Hopwood <david-sarah@…>]

In e821c9e23dd286734e7ebf0fbd17fa1fa5f4ff31/trunk:

Add a test for raising NotEnoughSharesError? when a Retrieve object is created with an insufficient servermap. refs #1742

Signed-off-by: Daira Hopwood <david-sarah@…>

[Daira Hopwood <david-sarah@…>]

In e821c9e23dd286734e7ebf0fbd17fa1fa5f4ff31/trunk:

Add a test for raising NotEnoughSharesError? when a Retrieve object is created with an insufficient servermap. refs #1742

Signed-off-by: Daira Hopwood <david-sarah@…>

[Daira Hopwood <david-sarah@…>]

In 705c47f9e92c4dfc010ccc124a8c814ebeabb197/trunk:

Improvements to test refs #1742

Signed-off-by: Daira Hopwood <david-sarah@…>

[Daira Hopwood <david-sarah@…>]

In 705c47f9e92c4dfc010ccc124a8c814ebeabb197/trunk:

Improvements to test refs #1742

Signed-off-by: Daira Hopwood <david-sarah@…>

[daira]

Hmm, we seem to be getting a trac notification for each github branch that a patch is pushed to (the above patches were pushed to both master and 1742-error-during-post on the official repo), but the branch name shown by trac is always /trunk.

[filed as #1970]

[daira]

As shown by the test, the assertion was triggered when a version obtained by, e.g. servermap.best_recoverable_version() is used with a (different) new or updated servermap, created after shares of that version have been lost.

Note that using the version obtained by calling best_recoverable_version() on the new/updated servermap would not trigger the assertion. This may explain why it triggered relatively rarely, or why it was coded as an assertion.

[warner]

Milestone renamed

[warner]

renaming milestone

[exarkun]

Moving open issues out of closed milestones.

[meejah]

Ticket retargeted after milestone closed