KeyError in mutable read-modify-write #1670

Open
opened 2012-02-10 07:27:40 +00:00 by vikarti · 46 comments
vikarti commented 2012-02-10 07:27:40 +00:00
Owner

Mac OS X 10.7 gateway,

mutable.format is set to mdmf

sometimes tahoe backup process several files fine and later stops
if it stops - it's always same place
like this

skipping "/Users/vikarti/Calibre Library/Zooko Wilcox-O'Hearn_ Brian Warner/Tahoe - The Least-Authority Filesystem (1347)/Tahoe - The Least-Authority Filesystem - Zooko Wilcox-O'Hearn_ Brian Warner.pdf"..
 re-using old directory for "/Users/vikarti/Calibre Library/Zooko Wilcox-O'Hearn_ Brian Warner/Tahoe - The Least-Authority Filesystem (1347)"
 re-using old directory for "/Users/vikarti/Calibre Library/Zooko Wilcox-O'Hearn_ Brian Warner"
 re-using old directory for '/Users/vikarti/Calibre Library'
Traceback (most recent call last):
  File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/support/bin/tahoe", line 9, in <module>
    load_entry_point('allmydata-tahoe==1.9.1', 'console_scripts', 'tahoe')()
  File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/runner.py", line 113, in run
    rc = runner(sys.argv[1:], install_node_control=install_node_control)
  File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/runner.py", line 99, in runner
    rc = cli.dispatch[command](so)
  File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/cli.py", line 569, in backup
    rc = tahoe_backup.backup(options)
  File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/tahoe_backup.py", line 325, in backup
    return bu.run()
  File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/tahoe_backup.py", line 123, in run
    put_child(archives_url, now, new_backup_dircap)
  File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/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 \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/base.py\", line 793, in runUntilCurrent
    call.func(*call.args, **call.kw)
  File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/support/lib/python2.7/site-packages/foolscap-0.6.3-py2.7.egg/foolscap/eventual.py\", line 26, in _turn
    cb(*args, **kwargs)\x0a  File \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py\", line 361, in callback
    self._startRunCallbacks(result)\x0a  File \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py\", line 455, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py\", line 542, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 855, in <lambda>\x0a    self._modify_once(modifier, first_time))\x0a  File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 881, in _modify_once
    d = self._try_to_download_data()
  File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 959, in _try_to_download_data
    d = self._read(c, fetch_privkey=True)
  File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 980, in _read
    d = r.download(consumer, offset, size)
  File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/retrieve.py\", line 237, in download
    self._setup_download()
  File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/retrieve.py\", line 277, in _setup_download
    shares = versionmap[self.verinfo]\x0aexceptions.KeyError: (5, '\\x11c\\x1c\\xf7\\xc9\\xae1e\\xa2\\xdaF\\xaf\\xb6S\\x03IH\\x84\\x11#\\xb5\\xf2TS\\xfb\\xde\\x08\\x81\\x01\\xf0\\xd3\\xec', None, 131073, 1080, 3, 10,
'\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x05\\x11c\\x1c\\xf7\\xc9\\xae1e\\xa2\\xdaF\\xaf\\xb6S\\x03IH\\x84\\x11#\\xb5\\xf2TS\\xfb\\xde\\x08\\x81\\x01\\xf0\\xd3\\xec\\x03\\n\\x00\\x00\\x00\\x00\\x00\\x02\\x00\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x048',
(('EOF', 2575), ('verification_key', 1729), ('enc_privkey', 123), ('share_data', 2167), ('signature', 1473), ('block_hash_tree', 2543), ('share_hash_chain', 1337), ('verification_key_end', 2021)))
"
Mac OS X 10.7 gateway, mutable.format is set to mdmf sometimes tahoe backup process several files fine and later stops if it stops - it's always same place like this ``` skipping "/Users/vikarti/Calibre Library/Zooko Wilcox-O'Hearn_ Brian Warner/Tahoe - The Least-Authority Filesystem (1347)/Tahoe - The Least-Authority Filesystem - Zooko Wilcox-O'Hearn_ Brian Warner.pdf".. re-using old directory for "/Users/vikarti/Calibre Library/Zooko Wilcox-O'Hearn_ Brian Warner/Tahoe - The Least-Authority Filesystem (1347)" re-using old directory for "/Users/vikarti/Calibre Library/Zooko Wilcox-O'Hearn_ Brian Warner" re-using old directory for '/Users/vikarti/Calibre Library' Traceback (most recent call last): File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/support/bin/tahoe", line 9, in <module> load_entry_point('allmydata-tahoe==1.9.1', 'console_scripts', 'tahoe')() File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/runner.py", line 113, in run rc = runner(sys.argv[1:], install_node_control=install_node_control) File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/runner.py", line 99, in runner rc = cli.dispatch[command](so) File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/cli.py", line 569, in backup rc = tahoe_backup.backup(options) File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/tahoe_backup.py", line 325, in backup return bu.run() File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/scripts/tahoe_backup.py", line 123, in run put_child(archives_url, now, new_backup_dircap) File "/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/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 \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/base.py\", line 793, in runUntilCurrent call.func(*call.args, **call.kw) File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/support/lib/python2.7/site-packages/foolscap-0.6.3-py2.7.egg/foolscap/eventual.py\", line 26, in _turn cb(*args, **kwargs)\x0a File \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py\", line 361, in callback self._startRunCallbacks(result)\x0a File \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py\", line 455, in _startRunCallbacks self._runCallbacks() --- <exception caught here> --- File \"/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py\", line 542, in _runCallbacks current.result = callback(current.result, *args, **kw) File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 855, in <lambda>\x0a self._modify_once(modifier, first_time))\x0a File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 881, in _modify_once d = self._try_to_download_data() File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 959, in _try_to_download_data d = self._read(c, fetch_privkey=True) File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/filenode.py\", line 980, in _read d = r.download(consumer, offset, size) File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/retrieve.py\", line 237, in download self._setup_download() File \"/Users/vikarti/tahoe-new/allmydata-tahoe-1.9.1/src/allmydata/mutable/retrieve.py\", line 277, in _setup_download shares = versionmap[self.verinfo]\x0aexceptions.KeyError: (5, '\\x11c\\x1c\\xf7\\xc9\\xae1e\\xa2\\xdaF\\xaf\\xb6S\\x03IH\\x84\\x11#\\xb5\\xf2TS\\xfb\\xde\\x08\\x81\\x01\\xf0\\xd3\\xec', None, 131073, 1080, 3, 10, '\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x05\\x11c\\x1c\\xf7\\xc9\\xae1e\\xa2\\xdaF\\xaf\\xb6S\\x03IH\\x84\\x11#\\xb5\\xf2TS\\xfb\\xde\\x08\\x81\\x01\\xf0\\xd3\\xec\\x03\\n\\x00\\x00\\x00\\x00\\x00\\x02\\x00\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x048', (('EOF', 2575), ('verification_key', 1729), ('enc_privkey', 123), ('share_data', 2167), ('signature', 1473), ('block_hash_tree', 2543), ('share_hash_chain', 1337), ('verification_key_end', 2021))) " ```
tahoe-lafs added the
c/unknown
p/major
t/defect
v/1.9.1
labels 2012-02-10 07:27:40 +00:00
tahoe-lafs added this to the undecided milestone 2012-02-10 07:27:40 +00:00
vikarti commented 2012-02-10 07:40:50 +00:00
Author
Owner

Attachment incident-2012-02-10--07-10-36Z-yyfpk7a.flog.bz2 (42352 bytes) added

possible related incident file 1

**Attachment** incident-2012-02-10--07-10-36Z-yyfpk7a.flog.bz2 (42352 bytes) added possible related incident file 1
vikarti commented 2012-02-10 07:41:03 +00:00
Author
Owner

Attachment incident-2012-02-10--07-11-26Z-qwg5ivy.flog.bz2 (42111 bytes) added

possible related incident file 2

**Attachment** incident-2012-02-10--07-11-26Z-qwg5ivy.flog.bz2 (42111 bytes) added possible related incident file 2
vikarti commented 2012-02-10 07:41:19 +00:00
Author
Owner

Attachment incident-2012-02-10--07-14-46Z-fpevtli.flog.bz2 (42576 bytes) added

possible related incident file 3

**Attachment** incident-2012-02-10--07-14-46Z-fpevtli.flog.bz2 (42576 bytes) added possible related incident file 3

reformat description

reformat description
daira added
c/code-mutable
and removed
c/unknown
labels 2012-02-17 18:43:24 +00:00
daira changed title from tahoe backup sometimes fails to KeyError in mutable MDMF retrieve 2012-02-17 18:43:24 +00:00

#1656 is a probable duplicate with a KeyError on the same line. Based on that, the bug doesn't seem to be specific to MDMF; vikarti, can you confirm that by trying to reproduce it with SDMF?

#1656 is a probable duplicate with a KeyError on the same line. Based on that, the bug doesn't seem to be specific to MDMF; vikarti, can you confirm that by trying to reproduce it with SDMF?
daira modified the milestone from undecided to soon 2012-02-19 00:59:47 +00:00
daira changed title from KeyError in mutable MDMF retrieve to KeyError in mutable retrieve 2012-02-19 00:59:47 +00:00
zooko added
p/critical
and removed
p/major
labels 2012-02-19 01:52:39 +00:00

Attachment 1656-tahoe-repair-incident-2012-02-18--22_59_20Z-fsyvi7q.flog.bz2 (41405 bytes) added

Incident file for 'tahoe deep-check --repair' from #1656

**Attachment** 1656-tahoe-repair-incident-2012-02-18--22_59_20Z-fsyvi7q.flog.bz2 (41405 bytes) added Incident file for 'tahoe deep-check --repair' from #1656
vikarti commented 2012-02-19 04:43:17 +00:00
Author
Owner

davidsarah, I can't reproduce this one on SDMF, it just either happens or not. If it will happen with SDMF - I will report here.

davidsarah, I can't reproduce this one on SDMF, it just either happens or not. If it will happen with SDMF - I will report here.
vikarti commented 2012-02-19 06:32:13 +00:00
Author
Owner

Davidsarah,
possible related to this:
SDMF directory, 2 tahoe backup sessions from different gateways to this directory,
2nd one got:

Unable to create target directory: 500 Internal Server Error
"Traceback (most recent call last):\x0a  File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\\twisted-10.1.0-py2.6-win-amd64.egg\\twisted\\inte
rnet\\base.py\", line 796, in runUntilCurrent\x0a    call.func(*call.args, **call.kw)\x0a  File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\
\foolscap-0.6.3-py2.6.egg\\foolscap\\eventual.py\", line 26, in _turn\x0a    cb(*args, **kwargs)\x0a  File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\sit
e-packages\\twisted-10.1.0-py2.6-win-amd64.egg\\twisted\\internet\\defer.py\", line 318, in callback\x0a    self._startRunCallbacks(result)\x0a  File \"C:\\Taho
e\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\\twisted-10.1.0-py2.6-win-amd64.egg\\twisted\\internet\\defer.py\", line 424, in _startRunCallbacks\x0a
 self._runCallbacks()\x0a--- <exception caught here> ---\x0a  File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\\twisted-10.1.0-py2.6-win-amd
64.egg\\twisted\\internet\\defer.py\", line 441, in _runCallbacks\x0a    self.result = callback(self.result, *args, **kw)\x0a  File \"c:\\tahoe\\allmydata-tahoe
-1.9.1\\src\\allmydata\\mutable\\filenode.py\", line 855, in <lambda>\x0a    self._modify_once(modifier, first_time))\x0a  File \"c:\\tahoe\\allmydata-tahoe-1.9
.1\\src\\allmydata\\mutable\\filenode.py\", line 881, in _modify_once\x0a    d = self._try_to_download_data()\x0a  File \"c:\\tahoe\\allmydata-tahoe-1.9.1\\src\
\allmydata\\mutable\\filenode.py\", line 959, in _try_to_download_data\x0a    d = self._read(c, fetch_privkey=True)\x0a  File \"c:\\tahoe\\allmydata-tahoe-1.9.1
\\src\\allmydata\\mutable\\filenode.py\", line 980, in _read\x0a    d = r.download(consumer, offset, size)\x0a  File \"c:\\tahoe\\allmydata-tahoe-1.9.1\\src\\al
lmydata\\mutable\\retrieve.py\", line 237, in download\x0a    self._setup_download()\x0a  File \"c:\\tahoe\\allmydata-tahoe-1.9.1\\src\\allmydata\\mutable\\retr
ieve.py\", line 277, in _setup_download\x0a    shares = versionmap[self.verinfo]\x0aexceptions.KeyError: (1, '@E\\xe0H\\x8a\\xbc\\xa6rQA\\xfa\\xab\\xfd&B\\xf6td
\"jv\\xae\\x96\\xccel\\xcf\\xc2\\x9f\\x8aG)', '\\xde\\xdeyKb\\xcc\\x8f-\\xed\\xea\\xa7\\xcc\\xe1a\\xfe\\x10', 0, 0, 4, 13, '\\x00\\x00\\x00\\x00\\x00\\x00\\x00\
\x00\\x01@E\\xe0H\\x8a\\xbc\\xa6rQA\\xfa\\xab\\xfd&B\\xf6td\"jv\\xae\\x96\\xccel\\xcf\\xc2\\x9f\\x8aG)\\xde\\xdeyKb\\xcc\\x8f-\\xed\\xea\\xa7\\xcc\\xe1a\\xfe\\x
10\\x04\\r\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00', (('enc_privkey', 823), ('EOF', 2038), ('share_data', 823), ('signat
ure', 399), ('block_hash_tree', 791), ('share_hash_chain', 655)))\x0a"

I think this is possible related to this ticket so reporting there.
also, there is inciden file for this one(attaching it)

Davidsarah, possible related to this: SDMF directory, 2 tahoe backup sessions from different gateways to this directory, 2nd one got: ``` Unable to create target directory: 500 Internal Server Error "Traceback (most recent call last):\x0a File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\\twisted-10.1.0-py2.6-win-amd64.egg\\twisted\\inte rnet\\base.py\", line 796, in runUntilCurrent\x0a call.func(*call.args, **call.kw)\x0a File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\ \foolscap-0.6.3-py2.6.egg\\foolscap\\eventual.py\", line 26, in _turn\x0a cb(*args, **kwargs)\x0a File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\sit e-packages\\twisted-10.1.0-py2.6-win-amd64.egg\\twisted\\internet\\defer.py\", line 318, in callback\x0a self._startRunCallbacks(result)\x0a File \"C:\\Taho e\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\\twisted-10.1.0-py2.6-win-amd64.egg\\twisted\\internet\\defer.py\", line 424, in _startRunCallbacks\x0a self._runCallbacks()\x0a--- <exception caught here> ---\x0a File \"C:\\Tahoe\\allmydata-tahoe-1.9.1\\support\\Lib\\site-packages\\twisted-10.1.0-py2.6-win-amd 64.egg\\twisted\\internet\\defer.py\", line 441, in _runCallbacks\x0a self.result = callback(self.result, *args, **kw)\x0a File \"c:\\tahoe\\allmydata-tahoe -1.9.1\\src\\allmydata\\mutable\\filenode.py\", line 855, in <lambda>\x0a self._modify_once(modifier, first_time))\x0a File \"c:\\tahoe\\allmydata-tahoe-1.9 .1\\src\\allmydata\\mutable\\filenode.py\", line 881, in _modify_once\x0a d = self._try_to_download_data()\x0a File \"c:\\tahoe\\allmydata-tahoe-1.9.1\\src\ \allmydata\\mutable\\filenode.py\", line 959, in _try_to_download_data\x0a d = self._read(c, fetch_privkey=True)\x0a File \"c:\\tahoe\\allmydata-tahoe-1.9.1 \\src\\allmydata\\mutable\\filenode.py\", line 980, in _read\x0a d = r.download(consumer, offset, size)\x0a File \"c:\\tahoe\\allmydata-tahoe-1.9.1\\src\\al lmydata\\mutable\\retrieve.py\", line 237, in download\x0a self._setup_download()\x0a File \"c:\\tahoe\\allmydata-tahoe-1.9.1\\src\\allmydata\\mutable\\retr ieve.py\", line 277, in _setup_download\x0a shares = versionmap[self.verinfo]\x0aexceptions.KeyError: (1, '@E\\xe0H\\x8a\\xbc\\xa6rQA\\xfa\\xab\\xfd&B\\xf6td \"jv\\xae\\x96\\xccel\\xcf\\xc2\\x9f\\x8aG)', '\\xde\\xdeyKb\\xcc\\x8f-\\xed\\xea\\xa7\\xcc\\xe1a\\xfe\\x10', 0, 0, 4, 13, '\\x00\\x00\\x00\\x00\\x00\\x00\\x00\ \x00\\x01@E\\xe0H\\x8a\\xbc\\xa6rQA\\xfa\\xab\\xfd&B\\xf6td\"jv\\xae\\x96\\xccel\\xcf\\xc2\\x9f\\x8aG)\\xde\\xdeyKb\\xcc\\x8f-\\xed\\xea\\xa7\\xcc\\xe1a\\xfe\\x 10\\x04\\r\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00', (('enc_privkey', 823), ('EOF', 2038), ('share_data', 823), ('signat ure', 399), ('block_hash_tree', 791), ('share_hash_chain', 655)))\x0a" ``` I think this is possible related to this ticket so reporting there. also, there is inciden file for this one(attaching it)
vikarti commented 2012-02-19 06:33:06 +00:00
Author
Owner

Attachment incident-2012-02-19--06-26-28Z-o6fb6qy.flog.bz2 (38106 bytes) added

possibl related incident file(see comment 7)

**Attachment** incident-2012-02-19--06-26-28Z-o6fb6qy.flog.bz2 (38106 bytes) added possibl related incident file(see comment 7)

vikarti: thanks, that confirms this problem is not specific to MDMF.

vikarti: thanks, that confirms this problem is not specific to MDMF.
kevan commented 2012-02-20 00:55:11 +00:00
Author
Owner

It looks like the mutable filenode modification code in MutableFileVersion reacts to an UncoordinatedWriteError by performing a map update, then trying the operation again. That map update will update the MutableFileVersion's internal servermap, but not its internal verinfo tuple. If the UncoordinatedWriteError is due to a concurrent update operation that updated all or most (enough for the version to be unrecoverable, anyway) of the shares associated with the MutableFileVersion's version of the mutable file, then we would see the KeyError reported by vikarti and others. Someone (likely me, if no one gets around to it before next weekend) should look over the incident logs to see if they support or refute this theory.

It looks like the mutable filenode modification code in `MutableFileVersion` reacts to an `UncoordinatedWriteError` by performing a map update, then trying the operation again. That map update will update the `MutableFileVersion`'s internal servermap, but not its internal verinfo tuple. If the `UncoordinatedWriteError` is due to a concurrent update operation that updated all or most (enough for the version to be unrecoverable, anyway) of the shares associated with the `MutableFileVersion`'s version of the mutable file, then we would see the `KeyError` reported by vikarti and others. Someone (likely me, if no one gets around to it before next weekend) should look over the incident logs to see if they support or refute this theory.

Attachment 1656-tahoe-put-incident-2012-02-18--22_00_17Z-7jusaxa.flog.bz2 (39376 bytes) added

Incident file for 'tahoe put' from #1656

**Attachment** 1656-tahoe-put-incident-2012-02-18--22_00_17Z-7jusaxa.flog.bz2 (39376 bytes) added Incident file for 'tahoe put' from #1656

This is a regression in 1.8→1.9, isn't it? I propose we put it into the "1.9.2" Milestone.

This is a regression in 1.8→1.9, isn't it? I propose we put it into the "1.9.2" Milestone.
zooko modified the milestone from soon to 1.9.2 2012-03-05 22:45:58 +00:00

huang jun provided some detailed debugging:

https://tahoe-lafs.org/pipermail/tahoe-dev/2012-April/007285.html

You have to read carefully to find where huang jun inserted comments and evidence from other log files. Look for the lines beginning with * or >.

huang jun provided some detailed debugging: <https://tahoe-lafs.org/pipermail/tahoe-dev/2012-April/007285.html> You have to read carefully to find where huang jun inserted comments and evidence from other log files. Look for the lines beginning with `*` or `>`.

Kyle Markley reported a bug with a similar stacktrace:

As I went about gathering information to submit a ticket, I discovered something interesting. This probably has something to do with the health of the target directories. I discovered one 2/4 directory that works cleanly, and another 2/4 directory that gives an error (after successfully creating the link). I haven't created a ticket yet because I'm not sure what's supposed to happen here. :)

Working directory:

$ tahoe check --raw kyle:
{
 "results": {
  "needs-rebalancing": true,
  "count-shares-expected": 4,
  "healthy": false,
  "count-unrecoverable-versions": 0,
  "count-shares-needed": 2,
  "sharemap": {
   "seq52-2x5m-sh3": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ],
   "seq52-2x5m-sh2": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ],
   "seq52-2x5m-sh1": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ],
   "seq52-2x5m-sh0": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ],
   "seq49-cqp3-sh2": [
    "juwmgssmwnhrhfdcpxxmrz3bghh37esx"
   ],
   "seq49-cqp3-sh3": [
    "vjqcroalrgmft66mgiwfjug667fl6qjd"
   ]
  },
  "count-recoverable-versions": 2,
  "servers-responding": [
   "vjqcroalrgmft66mgiwfjug667fl6qjd",
   "juwmgssmwnhrhfdcpxxmrz3bghh37esx",
   "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx",
   "47cslusczp3uu2kygodi3nlalcruscif",
   "eqtprtidz5emkvzlqt27dylgocdf3f77"
  ],
  "count-good-share-hosts": 1,
  "count-wrong-shares": 2,
  "count-shares-good": 4,
  "count-corrupt-shares": 0,
  "list-corrupt-shares": [],
  "recoverable": true
 },
 "storage-index": "rsi6ge4hmbzhxplyqjzkmd254e",
 "summary": "Unhealthy: multiple versions are recoverable"
}

Gives an error:

$ tahoe check --raw share:
{
 "results": {
  "needs-rebalancing": true,
  "count-shares-expected": 4,
  "healthy": false,
  "count-unrecoverable-versions": 1,
  "count-shares-needed": 2,
  "sharemap": {
   "seq45-7bxx-sh3": [
    "juwmgssmwnhrhfdcpxxmrz3bghh37esx"
   ],
   "seq46-jiym-sh1": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ],
   "seq46-jiym-sh0": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ],
   "seq56-aiot-sh0": [
    "vjqcroalrgmft66mgiwfjug667fl6qjd"
   ],
   "seq56-aiot-sh1": [
    "vjqcroalrgmft66mgiwfjug667fl6qjd"
   ],
   "seq56-aiot-sh2": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ],
   "seq56-aiot-sh3": [
    "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx"
   ]
  },
  "count-recoverable-versions": 2,
  "servers-responding": [
   "vjqcroalrgmft66mgiwfjug667fl6qjd",
   "juwmgssmwnhrhfdcpxxmrz3bghh37esx",
   "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx",
   "47cslusczp3uu2kygodi3nlalcruscif",
   "eqtprtidz5emkvzlqt27dylgocdf3f77"
  ],
  "count-good-share-hosts": 2,
  "count-wrong-shares": 3,
  "count-shares-good": 4,
  "count-corrupt-shares": 0,
  "list-corrupt-shares": [],
  "recoverable": true
 },
 "storage-index": "lb2mpyg4fnznnfebfayevcdpki",
 "summary": "Unhealthy: some versions are unrecoverable multiple versions are recoverable"
}

My error looks something like this. The exact message has changed; it used to say there was an UncoordinatedWriteError, but my experimentation seems to have changed things a bit, and right now I only see that error mentioned in the incident report.

$ tahoe ln foo: share:foo
Error: 500 Internal Server Error
"Traceback (most recent call last):\x0a  File \"/usr/local/lib/python2.7/site-packages/twisted/internet/base.py\", line 800, in runUntilCurrent\x0a    call.func(*call.args, **call.kw)\x0a  File \"/usr/local/lib/python2.7/site-packages/foolscap-0.6.3-py2.7.egg/foolscap/eventual.py\", line 26, in _turn\x0a    cb(*args, **kwargs)\x0a  File \"/usr/local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 368, in callback\x0a    self._startRunCallbacks(result)\x0a  File \"/usr/local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 464, in _startRunCallbacks\x0a    self._runCallbacks()\x0a--- <exception caught here> ---\x0a  File \"/usr/local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 551, in _runCallbacks\x0a    current.result = callback(current.result, *args, **kw)\x0a  File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 855, in <lambda>\x0a    self._modify_once(modifier, first_time))\x0a  File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 881, in _modify_once\x0a    d = self._try_to_download_data()\x0a  File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 959, in _try_to_download_data\x0a    d = self._read(c, fetch_privkey=True)\x0a  File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 980, in _read\x0a    d = r.download(consumer, offset, size)\x0a  File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 237, in download\x0a    self._setup_download()\x0a  File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 277, in _setup_download\x0a    shares = versionmap[self.verinfo]\x0aexceptions.KeyError: (57, '\\x16i\\xdb\\xa8\\xbc\\xd7\\xabrY\\xcdpv\\xa4I\\x82\\xfe\\xa5i\\xed\\x82;\\xca\\xe8\\xcaL\\xf7\\xdav\\xa9\\xf2O\\t', '\\x19f_S!&\\xb0\\xa1\\xeb\\x94\\x81F)\\xbb\\x89q', 336, 335, 2, 4, '\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x009\\x16i\\xdb\\xa8\\xbc\\xd7\\xabrY\\xcdpv\\xa4I\\x82\\xfe\\xa5i\\xed\\x82;\\xca\\xe8\\xcaL\\xf7\\xdav\\xa9\\xf2O\\t\\x19f_S!&\\xb0\\xa1\\xeb\\x94\\x81F)\\xbb\\x89q\\x02\\x04\\x00\\x00\\x00\\x00\\x00\\x00\\x01P\\x00\\x00\\x00\\x00\\x00\\x00\\x01O', (('enc_privkey', 923), ('EOF', 2138), ('share_data', 755), ('signature', 399), ('block_hash_tree', 723), ('share_hash_chain', 655)))\x0a"

From the incident report:

local#11372110 21:30:59.251: current goal: before update: , sh0 to [vjqcroal], sh0 to [xxaj2tgm], sh1 to [vjqcroal], sh1 to [xxaj2tgm], sh2 to [xxaj2tgm], sh3 to [juwmgssm], sh3 to [xxaj2tgm]
local#11372111 21:30:59.251: we are planning to push new seqnum=#58
local#11372112 21:30:59.252: Starting push
local#11372113 21:30:59.252: Pushing segment 1 of 1
local#11372114 21:30:59.275: storage: slot_writev lb2mpyg4fnznnfebfayevcdpki
local#11372115 21:30:59.277: storage: slot_writev lb2mpyg4fnznnfebfayevcdpki
local#11372116 21:30:59.281: _got_write_answer from xxaj2tgm, share 2
local#11372117 21:30:59.281: found the following surprise shares: set([0, 1])
local#11372118 21:30:59.281: they had shares [0, 1] that we didn't know about [INCIDENT-TRIGGER]
local#11372119 21:31:00.433: wrote successfully: adding new share to servermap
local#11372120 21:31:00.435: _got_write_answer from xxaj2tgm, share 3
local#11372121 21:31:00.435: found the following surprise shares: set([0, 1])
local#11372122 21:31:00.435: they had shares [0, 1] that we didn't know about
local#11372123 21:31:00.435: wrote successfully: adding new share to servermap
local#11372124 21:31:00.436: _got_write_answer from vjqcroal, share 0
local#11372125 21:31:00.436: found the following surprise shares: set([])
local#11372126 21:31:00.436: wrote successfully: adding new share to servermap
local#11372127 21:31:00.437: _got_write_answer from vjqcroal, share 1
local#11372128 21:31:00.437: found the following surprise shares: set([])
local#11372129 21:31:00.437: wrote successfully: adding new share to servermap
local#11372130 21:31:00.437: Publish failed with UncoordinatedWriteError

What's up with these surprise shares?
Kyle Markley reported a bug with a similar stacktrace: > As I went about gathering information to submit a ticket, I discovered something interesting. This probably has something to do with the health of the target directories. I discovered one 2/4 directory that works cleanly, and another 2/4 directory that gives an error (after *successfully* creating the link). I haven't created a ticket yet because I'm not sure what's supposed to happen here. :) > Working directory: ``` $ tahoe check --raw kyle: { "results": { "needs-rebalancing": true, "count-shares-expected": 4, "healthy": false, "count-unrecoverable-versions": 0, "count-shares-needed": 2, "sharemap": { "seq52-2x5m-sh3": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ], "seq52-2x5m-sh2": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ], "seq52-2x5m-sh1": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ], "seq52-2x5m-sh0": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ], "seq49-cqp3-sh2": [ "juwmgssmwnhrhfdcpxxmrz3bghh37esx" ], "seq49-cqp3-sh3": [ "vjqcroalrgmft66mgiwfjug667fl6qjd" ] }, "count-recoverable-versions": 2, "servers-responding": [ "vjqcroalrgmft66mgiwfjug667fl6qjd", "juwmgssmwnhrhfdcpxxmrz3bghh37esx", "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx", "47cslusczp3uu2kygodi3nlalcruscif", "eqtprtidz5emkvzlqt27dylgocdf3f77" ], "count-good-share-hosts": 1, "count-wrong-shares": 2, "count-shares-good": 4, "count-corrupt-shares": 0, "list-corrupt-shares": [], "recoverable": true }, "storage-index": "rsi6ge4hmbzhxplyqjzkmd254e", "summary": "Unhealthy: multiple versions are recoverable" } ``` > Gives an error: ``` $ tahoe check --raw share: { "results": { "needs-rebalancing": true, "count-shares-expected": 4, "healthy": false, "count-unrecoverable-versions": 1, "count-shares-needed": 2, "sharemap": { "seq45-7bxx-sh3": [ "juwmgssmwnhrhfdcpxxmrz3bghh37esx" ], "seq46-jiym-sh1": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ], "seq46-jiym-sh0": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ], "seq56-aiot-sh0": [ "vjqcroalrgmft66mgiwfjug667fl6qjd" ], "seq56-aiot-sh1": [ "vjqcroalrgmft66mgiwfjug667fl6qjd" ], "seq56-aiot-sh2": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ], "seq56-aiot-sh3": [ "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx" ] }, "count-recoverable-versions": 2, "servers-responding": [ "vjqcroalrgmft66mgiwfjug667fl6qjd", "juwmgssmwnhrhfdcpxxmrz3bghh37esx", "xxaj2tgmnl7debjdpn4mgv2oks6pjjnx", "47cslusczp3uu2kygodi3nlalcruscif", "eqtprtidz5emkvzlqt27dylgocdf3f77" ], "count-good-share-hosts": 2, "count-wrong-shares": 3, "count-shares-good": 4, "count-corrupt-shares": 0, "list-corrupt-shares": [], "recoverable": true }, "storage-index": "lb2mpyg4fnznnfebfayevcdpki", "summary": "Unhealthy: some versions are unrecoverable multiple versions are recoverable" } ``` > My error looks something like this. The exact message has changed; it used to say there was an `UncoordinatedWriteError`, but my experimentation seems to have changed things a bit, and right now I only see that error mentioned in the incident report. ``` $ tahoe ln foo: share:foo Error: 500 Internal Server Error "Traceback (most recent call last):\x0a File \"/usr/local/lib/python2.7/site-packages/twisted/internet/base.py\", line 800, in runUntilCurrent\x0a call.func(*call.args, **call.kw)\x0a File \"/usr/local/lib/python2.7/site-packages/foolscap-0.6.3-py2.7.egg/foolscap/eventual.py\", line 26, in _turn\x0a cb(*args, **kwargs)\x0a File \"/usr/local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 368, in callback\x0a self._startRunCallbacks(result)\x0a File \"/usr/local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 464, in _startRunCallbacks\x0a self._runCallbacks()\x0a--- <exception caught here> ---\x0a File \"/usr/local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 551, in _runCallbacks\x0a current.result = callback(current.result, *args, **kw)\x0a File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 855, in <lambda>\x0a self._modify_once(modifier, first_time))\x0a File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 881, in _modify_once\x0a d = self._try_to_download_data()\x0a File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 959, in _try_to_download_data\x0a d = self._read(c, fetch_privkey=True)\x0a File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 980, in _read\x0a d = r.download(consumer, offset, size)\x0a File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 237, in download\x0a self._setup_download()\x0a File \"/usr/local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 277, in _setup_download\x0a shares = versionmap[self.verinfo]\x0aexceptions.KeyError: (57, '\\x16i\\xdb\\xa8\\xbc\\xd7\\xabrY\\xcdpv\\xa4I\\x82\\xfe\\xa5i\\xed\\x82;\\xca\\xe8\\xcaL\\xf7\\xdav\\xa9\\xf2O\\t', '\\x19f_S!&\\xb0\\xa1\\xeb\\x94\\x81F)\\xbb\\x89q', 336, 335, 2, 4, '\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x009\\x16i\\xdb\\xa8\\xbc\\xd7\\xabrY\\xcdpv\\xa4I\\x82\\xfe\\xa5i\\xed\\x82;\\xca\\xe8\\xcaL\\xf7\\xdav\\xa9\\xf2O\\t\\x19f_S!&\\xb0\\xa1\\xeb\\x94\\x81F)\\xbb\\x89q\\x02\\x04\\x00\\x00\\x00\\x00\\x00\\x00\\x01P\\x00\\x00\\x00\\x00\\x00\\x00\\x01O', (('enc_privkey', 923), ('EOF', 2138), ('share_data', 755), ('signature', 399), ('block_hash_tree', 723), ('share_hash_chain', 655)))\x0a" ``` > From the incident report: ``` local#11372110 21:30:59.251: current goal: before update: , sh0 to [vjqcroal], sh0 to [xxaj2tgm], sh1 to [vjqcroal], sh1 to [xxaj2tgm], sh2 to [xxaj2tgm], sh3 to [juwmgssm], sh3 to [xxaj2tgm] local#11372111 21:30:59.251: we are planning to push new seqnum=#58 local#11372112 21:30:59.252: Starting push local#11372113 21:30:59.252: Pushing segment 1 of 1 local#11372114 21:30:59.275: storage: slot_writev lb2mpyg4fnznnfebfayevcdpki local#11372115 21:30:59.277: storage: slot_writev lb2mpyg4fnznnfebfayevcdpki local#11372116 21:30:59.281: _got_write_answer from xxaj2tgm, share 2 local#11372117 21:30:59.281: found the following surprise shares: set([0, 1]) local#11372118 21:30:59.281: they had shares [0, 1] that we didn't know about [INCIDENT-TRIGGER] local#11372119 21:31:00.433: wrote successfully: adding new share to servermap local#11372120 21:31:00.435: _got_write_answer from xxaj2tgm, share 3 local#11372121 21:31:00.435: found the following surprise shares: set([0, 1]) local#11372122 21:31:00.435: they had shares [0, 1] that we didn't know about local#11372123 21:31:00.435: wrote successfully: adding new share to servermap local#11372124 21:31:00.436: _got_write_answer from vjqcroal, share 0 local#11372125 21:31:00.436: found the following surprise shares: set([]) local#11372126 21:31:00.436: wrote successfully: adding new share to servermap local#11372127 21:31:00.437: _got_write_answer from vjqcroal, share 1 local#11372128 21:31:00.437: found the following surprise shares: set([]) local#11372129 21:31:00.437: wrote successfully: adding new share to servermap local#11372130 21:31:00.437: Publish failed with UncoordinatedWriteError What's up with these surprise shares? ```

Kevan, is Kyle's report consistent with comment:388664?

Kevan, is Kyle's report consistent with [comment:388664](/tahoe-lafs/trac/issues/1670#issuecomment-388664)?

Replying to kevan:

It looks like the mutable filenode modification code in MutableFileVersion reacts to an UncoordinatedWriteError by performing a map update, then trying the operation again.

Hm, that's interesting. Is this... intentional? Is this intended by someone? :-) I don't know right now whether I would intend that behavior.

A simpler behavior in response to UncoordinatedWriteError would be to abort the current operation and inform the user. That simpler behavior would presumably not have this bug in it, and maybe it would also avoid other potential problems caused by re-attempting an operation when there is evidence that someone else is uncoordinatedly changing the same file.

Replying to [kevan](/tahoe-lafs/trac/issues/1670#issuecomment-388664): > It looks like the mutable filenode modification code in `MutableFileVersion` reacts to an `UncoordinatedWriteError` by performing a map update, then trying the operation again. Hm, that's interesting. Is this... intentional? Is this intended by *someone*? :-) I don't know right now whether *I* would intend that behavior. A simpler behavior in response to `UncoordinatedWriteError` would be to abort the current operation and inform the user. That simpler behavior would presumably not have this bug in it, and maybe it would also avoid other potential problems caused by re-attempting an operation when there is evidence that someone else is uncoordinatedly changing the same file.

This looks like a similar error to #1772, so I'm investigating them both right now. Kevan, Brian, David-Sarah: if you are interested, please consider the question of whether we should simplify handling of UncoordinatedWriteError as suggested in comment:15. It seems to me like we currently handle UCWE complicatedly and buggily, and we should maybe change it to simpler and less buggy before attempting to change it to more complicated and featureful without being buggy. Just a thought. Anyway, I'll report what I learn about this...

This looks like a similar error to #1772, so I'm investigating them both right now. Kevan, Brian, David-Sarah: if you are interested, please consider the question of whether we should simplify handling of UncoordinatedWriteError as suggested in comment:15. It seems to me like we currently handle UCWE complicatedly and buggily, and we should maybe change it to simpler and less buggy before attempting to change it to more complicated and featureful without being buggy. Just a thought. Anyway, I'll report what I learn about this...

Sorry, I didn't mean #1772 (in comment:388671), I meant #1669.

Sorry, I didn't mean #1772 (in [comment:388671](/tahoe-lafs/trac/issues/1670#issuecomment-388671)), I meant #1669.

Replying to zooko:

please consider the question of whether we should simplify handling of UncoordinatedWriteError as suggested in comment:15.

Well, it looks like there is quite a lot of code to support the retrying of mutable operations, so I assumed that was certainly intentional (it was there before I joined the project, and I was mildly surprised since it seemed not entirely consistent with the "prime coordination directive"). Let's redesign it as part of designing two-phase commit, but not before 1.11. I really want to get 1.10 out with all the changes already on trunk, without making any more significant design changes.

Replying to [zooko](/tahoe-lafs/trac/issues/1670#issuecomment-388671): > please consider the question of whether we should simplify handling of UncoordinatedWriteError as suggested in comment:15. Well, it looks like there is quite a lot of code to support the retrying of mutable operations, so I assumed that was certainly intentional (it was there before I joined the project, and I was mildly surprised since it seemed not entirely consistent with the "prime coordination directive"). Let's redesign it as part of designing two-phase commit, but not before 1.11. I really want to get 1.10 out with all the changes already on trunk, without making any more significant design changes.

Fixed #1669 and it is different from this -- this isn't a duplicate.

By inspecting the bug reports and incident files I've confirmed what Kevan said, that the error happens during retry after a UCWE. One of the incident files shows the following:

02:26:28.641 [1920941]: current goal: before update: , sh0 to [fbil5app], sh1 to [d4f7ssed], sh2 to [lxur2oq3], sh3 to [rczho2ut], sh4 to [xi6zcwi2], sh5 to [zpm5ziqh], sh6 to [e5l3augd], sh7 to [yf6ahya4], sh8 to [7xdwosoe], sh9 to [t3zmoeba], sh10 to [lfc4wmmk], sh11 to [wasuxoux], sh12 to [iz3pbtdv]
    02:26:28.641 [1920942]: we are planning to push new seqnum=#2
    02:26:28.642 [1920943]: Starting push
    02:26:28.642 [1920944]: Pushing segment 1 of 1
    02:26:28.950 [1920945]: _got_write_answer from d4f7ssed, share 1
        02:26:28.950 [1920947]: WEIRD our testv failed, so the write did not happen [INCIDENT-TRIGGER]
        02:26:33.803 [1920948]: somebody modified the share on us: shnum=1: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:28.950 [1920946]: found the following surprise shares: set([])
    02:26:33.805 [1920949]: _got_write_answer from rczho2ut, share 3
        02:26:33.805 [1920951]: WEIRD our testv failed, so the write did not happen
        02:26:33.805 [1920952]: somebody modified the share on us: shnum=3: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.805 [1920950]: found the following surprise shares: set([])
    02:26:33.806 [1920953]: _got_write_answer from t3zmoeba, share 9
        02:26:33.806 [1920955]: WEIRD our testv failed, so the write did not happen
        02:26:33.806 [1920956]: somebody modified the share on us: shnum=9: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.806 [1920954]: found the following surprise shares: set([])
    02:26:33.812 [1920957]: _got_write_answer from fbil5app, share 0
        02:26:33.812 [1920959]: WEIRD our testv failed, so the write did not happen
        02:26:33.812 [1920960]: somebody modified the share on us: shnum=0: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.812 [1920958]: found the following surprise shares: set([])
    02:26:33.813 [1920961]: _got_write_answer from lfc4wmmk, share 10
        02:26:33.813 [1920963]: WEIRD our testv failed, so the write did not happen
        02:26:33.813 [1920964]: somebody modified the share on us: shnum=10: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.813 [1920962]: found the following surprise shares: set([])
    02:26:33.815 [1920965]: _got_write_answer from wasuxoux, share 11
        02:26:33.815 [1920967]: WEIRD our testv failed, so the write did not happen
        02:26:33.815 [1920968]: somebody modified the share on us: shnum=11: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.815 [1920966]: found the following surprise shares: set([])
    02:26:33.816 [1920969]: _got_write_answer from lxur2oq3, share 2
        02:26:33.816 [1920971]: WEIRD our testv failed, so the write did not happen
        02:26:33.818 [1920972]: somebody modified the share on us: shnum=2: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.816 [1920970]: found the following surprise shares: set([])
    02:26:33.819 [1920973]: _got_write_answer from 7xdwosoe, share 8
        02:26:33.819 [1920975]: WEIRD our testv failed, so the write did not happen
        02:26:33.819 [1920976]: somebody modified the share on us: shnum=8: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.819 [1920974]: found the following surprise shares: set([])
    02:26:33.819 [1920977]: _got_write_answer from iz3pbtdv, share 12
        02:26:33.819 [1920979]: WEIRD our testv failed, so the write did not happen
        02:26:33.821 [1920980]: somebody modified the share on us: shnum=12: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.819 [1920978]: found the following surprise shares: set([])
    02:26:33.822 [1920981]: _got_write_answer from e5l3augd, share 6
        02:26:33.822 [1920983]: WEIRD our testv failed, so the write did not happen
        02:26:33.822 [1920984]: somebody modified the share on us: shnum=6: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.822 [1920982]: found the following surprise shares: set([])
    02:26:33.882 [1920985]: _got_write_answer from zpm5ziqh, share 5
        02:26:33.882 [1920987]: WEIRD our testv failed, so the write did not happen
        02:26:33.882 [1920988]: somebody modified the share on us: shnum=5: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.882 [1920986]: found the following surprise shares: set([])
    02:26:33.884 [1920989]: _got_write_answer from xi6zcwi2, share 4
        02:26:33.884 [1920991]: WEIRD our testv failed, so the write did not happen
        02:26:33.884 [1920992]: somebody modified the share on us: shnum=4: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.884 [1920990]: found the following surprise shares: set([])
    02:26:33.885 [1920993]: _got_write_answer from yf6ahya4, share 7
        02:26:33.885 [1920995]: WEIRD our testv failed, so the write did not happen
        02:26:33.885 [1920996]: somebody modified the share on us: shnum=7: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2
    02:26:33.885 [1920994]: found the following surprise shares: set([])
    02:26:33.885 [1920997]: Publish failed with UncoordinatedWriteError

02:26:37.075 [1920998]: doing modify
02:26:37.075 [1920999]: SharemapUpdater(wmnt2): starting (MODE_CHECK)

    02:26:37.076 [1921000]: sending query to [iz3pbtdv], readsize=1000
    02:26:37.078 [1921001]: sending query to [rczho2ut], readsize=1000
    02:26:37.079 [1921002]: sending query to [lfc4wmmk], readsize=1000
    02:26:37.081 [1921003]: sending query to [yf6ahya4], readsize=1000
    02:26:37.082 [1921004]: sending query to [d4f7ssed], readsize=1000
    02:26:37.084 [1921005]: sending query to [t3zmoeba], readsize=1000
    02:26:37.085 [1921006]: sending query to [fbil5app], readsize=1000
    02:26:37.085 [1921007]: sending query to [xi6zcwi2], readsize=1000
    02:26:37.086 [1921008]: sending query to [wasuxoux], readsize=1000
    02:26:37.088 [1921009]: sending query to [7xdwosoe], readsize=1000
    02:26:37.088 [1921010]: sending query to [zpm5ziqh], readsize=1000
    02:26:37.089 [1921011]: sending query to [lxur2oq3], readsize=1000
    02:26:37.098 [1921012]: sending query to [e5l3augd], readsize=1000
    02:26:37.131 [1921013]: got result from [d4f7ssed], 1 shares
        02:26:37.131 [1921014]: _got_results done
        02:26:37.134 [1921019]: _got_results: got shnum #1 from peerid d4f7ssed
        02:26:37.134 [1921020]: found valid version 2-tmzg from d4f7ssed-sh1: 4-13/352/349
    02:26:37.131 [1921015]: got result from [rczho2ut], 1 shares
        02:26:37.132 [1921016]: _got_results done
        02:26:37.137 [1921025]: _got_results: got shnum #3 from peerid rczho2ut
        02:26:37.137 [1921026]: found valid version 2-tmzg from rczho2ut-sh3: 4-13/352/349
    02:26:37.134 [1921017]: got result from [t3zmoeba], 1 shares
        02:26:37.134 [1921018]: _got_results done
        02:26:37.138 [1921031]: _got_results: got shnum #9 from peerid t3zmoeba
        02:26:37.138 [1921032]: found valid version 2-tmzg from t3zmoeba-sh9: 4-13/352/349
    02:26:37.135 [1921021]: _check_for_done, mode is 'MODE_CHECK', 12 queries outstanding, 0 extra peers available, 12 'must query' peers left, need_privkey=False
        02:26:37.135 [1921022]: 12 'must query' peers left
    02:26:37.135 [1921023]: _check_for_done, mode is 'MODE_CHECK', 12 queries outstanding, 0 extra peers available, 12 'must query' peers left, need_privkey=False
        02:26:37.135 [1921024]: 12 'must query' peers left
    02:26:37.137 [1921027]: _check_for_done, mode is 'MODE_CHECK', 11 queries outstanding, 0 extra peers available, 11 'must query' peers left, need_privkey=False
        02:26:37.137 [1921028]: 11 'must query' peers left
    02:26:37.137 [1921029]: _check_for_done, mode is 'MODE_CHECK', 11 queries outstanding, 0 extra peers available, 11 'must query' peers left, need_privkey=False
        02:26:37.137 [1921030]: 11 'must query' peers left
    02:26:37.138 [1921033]: _check_for_done, mode is 'MODE_CHECK', 10 queries outstanding, 0 extra peers available, 10 'must query' peers left, need_privkey=False
        02:26:37.138 [1921034]: 10 'must query' peers left
    02:26:37.138 [1921035]: _check_for_done, mode is 'MODE_CHECK', 10 queries outstanding, 0 extra peers available, 10 'must query' peers left, need_privkey=False
        02:26:37.138 [1921036]: 10 'must query' peers left
    02:26:37.269 [1921037]: got result from [7xdwosoe], 1 shares
        02:26:37.270 [1921038]: _got_results done
        02:26:37.272 [1921039]: _got_results: got shnum #8 from peerid 7xdwosoe
        02:26:37.273 [1921040]: found valid version 2-tmzg from 7xdwosoe-sh8: 4-13/352/349
    02:26:37.273 [1921041]: _check_for_done, mode is 'MODE_CHECK', 9 queries outstanding, 0 extra peers available, 9 'must query' peers left, need_privkey=False
        02:26:37.273 [1921042]: 9 'must query' peers left
    02:26:37.273 [1921043]: _check_for_done, mode is 'MODE_CHECK', 9 queries outstanding, 0 extra peers available, 9 'must query' peers left, need_privkey=False
        02:26:37.273 [1921044]: 9 'must query' peers left
    02:26:37.319 [1921045]: got result from [lfc4wmmk], 1 shares
        02:26:37.319 [1921046]: _got_results done
        02:26:37.321 [1921047]: _got_results: got shnum #10 from peerid lfc4wmmk

And the user then reported the following:

  File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\filenode.py", line 855, in <lambda>
    self._modify_once(modifier, first_time))
  File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\filenode.py", line 881, in _modify_once
    d = self._try_to_download_data()
  File "c:\tahoe\allmydata-tahoe-1.9.1\srcllmydata\mutable\filenode.py", line 959, in _try_to_download_data
    d = self._read(c, fetch_privkey=True)
  File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\filenode.py", line 980, in _read
    d = r.download(consumer, offset, size)
  File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\retrieve.py", line 237, in download
    self._setup_download()
  File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\retrieve.py", line 277, in _setup_download
    shares = versionmap[self.verinfo]
exceptions.KeyError: (1, '@E\xe0H\x8a\xbc\xa6rQA\xfa\xab\xfd&B\xf6td"jv\xae\x96\xccel\xcf\xc2\x9f\x8aG)', '\xde\xdeyKb\xcc\x8f-\xed\xea\xa7\xcc\xe1a\xfe\x10', 0, 0, 4, 13, '\x00\x00\x00\x00\x00\x00\x00\x01@E\xe0H\x8a\xbc\xa6rQA\xfa\xab\xfd&B\xf6td"jv\xae\x96\xccel\xcf\xc2\x9f\x8aG)\xde\xdeyKb\xcc\x8f-\xed\xea\xa7\xcc\xe1a\xfe\x10\x04\r\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00', (('enc_privkey', 823), ('EOF', 2038), ('share_data', 823), ('signature', 399), ('block_hash_tree', 791), ('share_hash_chain', 655)))
Fixed #1669 and it is different from this -- this isn't a duplicate. By inspecting the bug reports and incident files I've confirmed what Kevan said, that the error happens during retry after a UCWE. One of the incident files shows the following: ``` 02:26:28.641 [1920941]: current goal: before update: , sh0 to [fbil5app], sh1 to [d4f7ssed], sh2 to [lxur2oq3], sh3 to [rczho2ut], sh4 to [xi6zcwi2], sh5 to [zpm5ziqh], sh6 to [e5l3augd], sh7 to [yf6ahya4], sh8 to [7xdwosoe], sh9 to [t3zmoeba], sh10 to [lfc4wmmk], sh11 to [wasuxoux], sh12 to [iz3pbtdv] 02:26:28.641 [1920942]: we are planning to push new seqnum=#2 02:26:28.642 [1920943]: Starting push 02:26:28.642 [1920944]: Pushing segment 1 of 1 02:26:28.950 [1920945]: _got_write_answer from d4f7ssed, share 1 02:26:28.950 [1920947]: WEIRD our testv failed, so the write did not happen [INCIDENT-TRIGGER] 02:26:33.803 [1920948]: somebody modified the share on us: shnum=1: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:28.950 [1920946]: found the following surprise shares: set([]) 02:26:33.805 [1920949]: _got_write_answer from rczho2ut, share 3 02:26:33.805 [1920951]: WEIRD our testv failed, so the write did not happen 02:26:33.805 [1920952]: somebody modified the share on us: shnum=3: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.805 [1920950]: found the following surprise shares: set([]) 02:26:33.806 [1920953]: _got_write_answer from t3zmoeba, share 9 02:26:33.806 [1920955]: WEIRD our testv failed, so the write did not happen 02:26:33.806 [1920956]: somebody modified the share on us: shnum=9: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.806 [1920954]: found the following surprise shares: set([]) 02:26:33.812 [1920957]: _got_write_answer from fbil5app, share 0 02:26:33.812 [1920959]: WEIRD our testv failed, so the write did not happen 02:26:33.812 [1920960]: somebody modified the share on us: shnum=0: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.812 [1920958]: found the following surprise shares: set([]) 02:26:33.813 [1920961]: _got_write_answer from lfc4wmmk, share 10 02:26:33.813 [1920963]: WEIRD our testv failed, so the write did not happen 02:26:33.813 [1920964]: somebody modified the share on us: shnum=10: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.813 [1920962]: found the following surprise shares: set([]) 02:26:33.815 [1920965]: _got_write_answer from wasuxoux, share 11 02:26:33.815 [1920967]: WEIRD our testv failed, so the write did not happen 02:26:33.815 [1920968]: somebody modified the share on us: shnum=11: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.815 [1920966]: found the following surprise shares: set([]) 02:26:33.816 [1920969]: _got_write_answer from lxur2oq3, share 2 02:26:33.816 [1920971]: WEIRD our testv failed, so the write did not happen 02:26:33.818 [1920972]: somebody modified the share on us: shnum=2: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.816 [1920970]: found the following surprise shares: set([]) 02:26:33.819 [1920973]: _got_write_answer from 7xdwosoe, share 8 02:26:33.819 [1920975]: WEIRD our testv failed, so the write did not happen 02:26:33.819 [1920976]: somebody modified the share on us: shnum=8: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.819 [1920974]: found the following surprise shares: set([]) 02:26:33.819 [1920977]: _got_write_answer from iz3pbtdv, share 12 02:26:33.819 [1920979]: WEIRD our testv failed, so the write did not happen 02:26:33.821 [1920980]: somebody modified the share on us: shnum=12: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.819 [1920978]: found the following surprise shares: set([]) 02:26:33.822 [1920981]: _got_write_answer from e5l3augd, share 6 02:26:33.822 [1920983]: WEIRD our testv failed, so the write did not happen 02:26:33.822 [1920984]: somebody modified the share on us: shnum=6: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.822 [1920982]: found the following surprise shares: set([]) 02:26:33.882 [1920985]: _got_write_answer from zpm5ziqh, share 5 02:26:33.882 [1920987]: WEIRD our testv failed, so the write did not happen 02:26:33.882 [1920988]: somebody modified the share on us: shnum=5: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.882 [1920986]: found the following surprise shares: set([]) 02:26:33.884 [1920989]: _got_write_answer from xi6zcwi2, share 4 02:26:33.884 [1920991]: WEIRD our testv failed, so the write did not happen 02:26:33.884 [1920992]: somebody modified the share on us: shnum=4: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.884 [1920990]: found the following surprise shares: set([]) 02:26:33.885 [1920993]: _got_write_answer from yf6ahya4, share 7 02:26:33.885 [1920995]: WEIRD our testv failed, so the write did not happen 02:26:33.885 [1920996]: somebody modified the share on us: shnum=7: I thought they had #1:R=ibc6, but testv reported #2:R=�2e!J&t����ܘvҐ:%��l�i�tA2 02:26:33.885 [1920994]: found the following surprise shares: set([]) 02:26:33.885 [1920997]: Publish failed with UncoordinatedWriteError 02:26:37.075 [1920998]: doing modify 02:26:37.075 [1920999]: SharemapUpdater(wmnt2): starting (MODE_CHECK) 02:26:37.076 [1921000]: sending query to [iz3pbtdv], readsize=1000 02:26:37.078 [1921001]: sending query to [rczho2ut], readsize=1000 02:26:37.079 [1921002]: sending query to [lfc4wmmk], readsize=1000 02:26:37.081 [1921003]: sending query to [yf6ahya4], readsize=1000 02:26:37.082 [1921004]: sending query to [d4f7ssed], readsize=1000 02:26:37.084 [1921005]: sending query to [t3zmoeba], readsize=1000 02:26:37.085 [1921006]: sending query to [fbil5app], readsize=1000 02:26:37.085 [1921007]: sending query to [xi6zcwi2], readsize=1000 02:26:37.086 [1921008]: sending query to [wasuxoux], readsize=1000 02:26:37.088 [1921009]: sending query to [7xdwosoe], readsize=1000 02:26:37.088 [1921010]: sending query to [zpm5ziqh], readsize=1000 02:26:37.089 [1921011]: sending query to [lxur2oq3], readsize=1000 02:26:37.098 [1921012]: sending query to [e5l3augd], readsize=1000 02:26:37.131 [1921013]: got result from [d4f7ssed], 1 shares 02:26:37.131 [1921014]: _got_results done 02:26:37.134 [1921019]: _got_results: got shnum #1 from peerid d4f7ssed 02:26:37.134 [1921020]: found valid version 2-tmzg from d4f7ssed-sh1: 4-13/352/349 02:26:37.131 [1921015]: got result from [rczho2ut], 1 shares 02:26:37.132 [1921016]: _got_results done 02:26:37.137 [1921025]: _got_results: got shnum #3 from peerid rczho2ut 02:26:37.137 [1921026]: found valid version 2-tmzg from rczho2ut-sh3: 4-13/352/349 02:26:37.134 [1921017]: got result from [t3zmoeba], 1 shares 02:26:37.134 [1921018]: _got_results done 02:26:37.138 [1921031]: _got_results: got shnum #9 from peerid t3zmoeba 02:26:37.138 [1921032]: found valid version 2-tmzg from t3zmoeba-sh9: 4-13/352/349 02:26:37.135 [1921021]: _check_for_done, mode is 'MODE_CHECK', 12 queries outstanding, 0 extra peers available, 12 'must query' peers left, need_privkey=False 02:26:37.135 [1921022]: 12 'must query' peers left 02:26:37.135 [1921023]: _check_for_done, mode is 'MODE_CHECK', 12 queries outstanding, 0 extra peers available, 12 'must query' peers left, need_privkey=False 02:26:37.135 [1921024]: 12 'must query' peers left 02:26:37.137 [1921027]: _check_for_done, mode is 'MODE_CHECK', 11 queries outstanding, 0 extra peers available, 11 'must query' peers left, need_privkey=False 02:26:37.137 [1921028]: 11 'must query' peers left 02:26:37.137 [1921029]: _check_for_done, mode is 'MODE_CHECK', 11 queries outstanding, 0 extra peers available, 11 'must query' peers left, need_privkey=False 02:26:37.137 [1921030]: 11 'must query' peers left 02:26:37.138 [1921033]: _check_for_done, mode is 'MODE_CHECK', 10 queries outstanding, 0 extra peers available, 10 'must query' peers left, need_privkey=False 02:26:37.138 [1921034]: 10 'must query' peers left 02:26:37.138 [1921035]: _check_for_done, mode is 'MODE_CHECK', 10 queries outstanding, 0 extra peers available, 10 'must query' peers left, need_privkey=False 02:26:37.138 [1921036]: 10 'must query' peers left 02:26:37.269 [1921037]: got result from [7xdwosoe], 1 shares 02:26:37.270 [1921038]: _got_results done 02:26:37.272 [1921039]: _got_results: got shnum #8 from peerid 7xdwosoe 02:26:37.273 [1921040]: found valid version 2-tmzg from 7xdwosoe-sh8: 4-13/352/349 02:26:37.273 [1921041]: _check_for_done, mode is 'MODE_CHECK', 9 queries outstanding, 0 extra peers available, 9 'must query' peers left, need_privkey=False 02:26:37.273 [1921042]: 9 'must query' peers left 02:26:37.273 [1921043]: _check_for_done, mode is 'MODE_CHECK', 9 queries outstanding, 0 extra peers available, 9 'must query' peers left, need_privkey=False 02:26:37.273 [1921044]: 9 'must query' peers left 02:26:37.319 [1921045]: got result from [lfc4wmmk], 1 shares 02:26:37.319 [1921046]: _got_results done 02:26:37.321 [1921047]: _got_results: got shnum #10 from peerid lfc4wmmk ``` And the user then reported the following: ``` File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\filenode.py", line 855, in <lambda> self._modify_once(modifier, first_time)) File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\filenode.py", line 881, in _modify_once d = self._try_to_download_data() File "c:\tahoe\allmydata-tahoe-1.9.1\srcllmydata\mutable\filenode.py", line 959, in _try_to_download_data d = self._read(c, fetch_privkey=True) File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\filenode.py", line 980, in _read d = r.download(consumer, offset, size) File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\retrieve.py", line 237, in download self._setup_download() File "c:\tahoe\allmydata-tahoe-1.9.1\src\allmydata\mutable\retrieve.py", line 277, in _setup_download shares = versionmap[self.verinfo] exceptions.KeyError: (1, '@E\xe0H\x8a\xbc\xa6rQA\xfa\xab\xfd&B\xf6td"jv\xae\x96\xccel\xcf\xc2\x9f\x8aG)', '\xde\xdeyKb\xcc\x8f-\xed\xea\xa7\xcc\xe1a\xfe\x10', 0, 0, 4, 13, '\x00\x00\x00\x00\x00\x00\x00\x01@E\xe0H\x8a\xbc\xa6rQA\xfa\xab\xfd&B\xf6td"jv\xae\x96\xccel\xcf\xc2\x9f\x8aG)\xde\xdeyKb\xcc\x8f-\xed\xea\xa7\xcc\xe1a\xfe\x10\x04\r\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00', (('enc_privkey', 823), ('EOF', 2038), ('share_data', 823), ('signature', 399), ('block_hash_tree', 791), ('share_hash_chain', 655))) ```

Hm, actually this may be the same underlying problem as in #1669. In #1669, we found that:

• [SDMFSlotWriteProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L433 and [MDMFSlotReadProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L1692 return the same shape of tuple, but [MDMFSlotWriteProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L1102 returns a different shape.

So, could this ticket (#1670) be caused by MDMFSlotWriteProxy.get_verinfo returning a differently-shaped verinfo, which gets used as a key in the Retrieve, and then later when MDMFSlotReadProxy.get_verinfo returns what ought to be the same thing (but isn't due to the different shape), and then the Retrieve looks it up in the versionmap, it gets a key error?

Hm, actually this may be the same underlying problem as in #1669. In #1669, we found that: • [SDMFSlotWriteProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L433 and [MDMFSlotReadProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L1692 return the same shape of tuple, but [MDMFSlotWriteProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L1102 returns a different shape. So, could this ticket (#1670) be caused by `MDMFSlotWriteProxy.get_verinfo` returning a differently-shaped verinfo, which gets used as a key in the `Retrieve`, and then later when `MDMFSlotReadProxy.get_verinfo` returns what ought to be the same thing (but isn't due to the different shape), and then the `Retrieve` looks it up in the `versionmap`, it gets a key error?
zooko added
v/1.9.0-s3branch
and removed
v/1.9.1
labels 2012-06-24 03:25:41 +00:00

Yes, I've looked at how the auto-retry functionality shown in the stack trace (comment:388674) works, and it looks like the earlier attempt to publish would indeed update the ServerMap object's self.servermap dict to have a verinfo returned by the MDMFSlotWriteProxy.get_verinfo. So I'm increasingly confident that the fix to #1669 also fixed this bug. The next step is to write a unit test that exercises the auto-retry functionality with MDMF, which should show the bug present in 1.9.1 and absent in 1.9.2a1.

(Also, by the way, I remain pretty interested in the idea of removing the auto-retry functionality completely.)

Yes, I've looked at how the auto-retry functionality shown in the stack trace ([comment:388674](/tahoe-lafs/trac/issues/1670#issuecomment-388674)) works, and it looks like the earlier attempt to publish would indeed update the `ServerMap` object's `self.servermap` dict to have a verinfo returned by the `MDMFSlotWriteProxy.get_verinfo`. So I'm increasingly confident that the fix to #1669 also fixed this bug. The next step is to write a unit test that exercises the auto-retry functionality with MDMF, which should show the bug present in 1.9.1 and absent in 1.9.2a1. (Also, by the way, I remain pretty interested in the idea of removing the auto-retry functionality completely.)

Did we fix the binary SIs (if that's what they are) in the log, BTW?

Did we fix the binary SIs (if that's what they are) in the log, BTW?
daira added
v/1.9.1
and removed
v/1.9.0-s3branch
labels 2012-06-24 21:47:34 +00:00

I haven't committed that patch yet. Wasn't planning to do for 1.9.2. Shall I?

I haven't committed that patch yet. Wasn't planning to do for 1.9.2. Shall I?

Replying to zooko:

I haven't committed that patch yet. Wasn't planning to do for 1.9.2. Shall I?

Please attach the patch here so I can decide whether to commit it for 1.9.2. It should be low-risk I think.

Replying to [zooko](/tahoe-lafs/trac/issues/1670#issuecomment-388682): > I haven't committed that patch yet. Wasn't planning to do for 1.9.2. Shall I? Please attach the patch here so I can decide whether to commit it for 1.9.2. It should be low-risk I think.

I think this bug can only happen for a read-modify-write.

I think this bug can only happen for a read-modify-write.
daira changed title from KeyError in mutable retrieve to KeyError in mutable read-modify-write 2012-07-02 16:24:28 +00:00
daira modified the milestone from 1.9.2 to 1.10.0 2012-07-03 20:28:43 +00:00
zooko changed title from KeyError in mutable read-modify-write to add tests for KeyError in mutable read-modify-write 2012-09-04 16:36:32 +00:00

Will look at adding a test.

Will look at adding a test.

Replying to davidsarah:

Did we fix the binary SIs (if that's what they are) in the log, BTW?

Split to #1800.

Replying to [davidsarah](/tahoe-lafs/trac/issues/1670#issuecomment-388679): > Did we fix the binary SIs (if that's what they are) in the log, BTW? Split to #1800.
zooko added
p/normal
and removed
p/critical
labels 2012-11-13 23:28:41 +00:00
daira modified the milestone from 1.10.0 to 1.11.0 2012-12-20 16:33:25 +00:00

News flash! joepie91 from IRC reported a bug which looks exactly like this one. However, he is using Tahoe-LAFS v1.9.2, with the patch from #1669 (changeset:5524/1.9.2) in place! This means that, contrary to what I thought, that patch did not fix this issue — #1670.

News flash! joepie91 from IRC reported a bug which looks exactly like this one. However, he is using Tahoe-LAFS v1.9.2, with the patch from #1669 (changeset:5524/1.9.2) in place! This means that, contrary to what I thought, that patch did not fix this issue — #1670.

Here is a stack trace from joepie91:

ata/mutable/filenode.py", line 885, in _modify_once
    d = self._try_to_download_data()
  File "/home/occupy/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 "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 985, in _read
    d = r.download(consumer, offset, size)
  File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 244, in download
    self._setup_download()
  File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 284, in _setup_download
    shares = versionmap[self.verinfo]
exceptions.KeyError: (42, "@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe", '4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2', 668, 666, 4, 8, "\x00\x00\x00\x00\x00\x00\x00\x00*@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2\x04\x08\x00\x00\x00\x00\x00\x00\x02\x9c\x00\x00\x00\x00\x00\x00\x02\x9a", (('enc_privkey', 956), ('EOF', 2172), ('share_data', 789), ('signature', 399), ('block_hash_tree', 757), ('share_hash_chain', 655)))
Here is a stack trace from joepie91: ``` ata/mutable/filenode.py", line 885, in _modify_once d = self._try_to_download_data() File "/home/occupy/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 "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 985, in _read d = r.download(consumer, offset, size) File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 244, in download self._setup_download() File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 284, in _setup_download shares = versionmap[self.verinfo] exceptions.KeyError: (42, "@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe", '4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2', 668, 666, 4, 8, "\x00\x00\x00\x00\x00\x00\x00\x00*@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2\x04\x08\x00\x00\x00\x00\x00\x00\x02\x9c\x00\x00\x00\x00\x00\x00\x02\x9a", (('enc_privkey', 956), ('EOF', 2172), ('share_data', 789), ('signature', 399), ('block_hash_tree', 757), ('share_hash_chain', 655))) ```

Attaching an incident report file from joepie91 that I manually filtered to remove potentially sensitive information.

Attaching an incident report file from joepie91 that I manually filtered to remove potentially sensitive information.

Attachment incident-2013-01-14--07-54-09Z-2ymyxfi.flog.bz2.dump.txt.manually-filtered.txt (286008 bytes) added

**Attachment** incident-2013-01-14--07-54-09Z-2ymyxfi.flog.bz2.dump.txt.manually-filtered.txt (286008 bytes) added

In attachment:incident-2013-01-14--07-54-09Z-2ymyxfi.flog.bz2.dump.txt.manually-filtered.txt, you can see that the KeyError was preceded by a mysteriously changed version number, probably due to a different gateway modifying the directory at the same time as this gateway was doing so:

local#197564 2013-01-14_05:30:14.753657Z:  found valid version 42-iatt from qenkbcot-sh3: 4-8/668/666

local#197629 2013-01-14_05:30:18.187664Z: we are planning to push new seqnum=#43

local#197655 2013-01-14_05:31:15.323720Z: our testv failed, so the write did not happen
local#197656 2013-01-14_05:31:17.737595Z: somebody modified the share on us: shnum=3: I thought they had #42:R=iatt, but testv reported #44:R=ÙUQ$žÌJè)C⑍vDíŽ[·²±ºŒNE#˜ÖG\Ö
local#197657 2013-01-14_05:31:17.737826Z: Publish failed with UncoordinatedWriteError

So then it does the automatic-merge-and-retry thing (which I would still like to remove, for simplicity):

local#197658 2013-01-14_05:31:21.260199Z: doing modify
local#197659 2013-01-14_05:31:21.260870Z: SharemapUpdater(i2sen): starting (MODE_CHECK)

local#197745 2013-01-14_05:31:22.504839Z: got result from [qenkbcot], 1 shares
local#197748 2013-01-14_05:31:22.509699Z:  found valid version 44-a3mv from qenkbcot-sh3: 4-8/668/665

But then it somehow uses a cached verinfo which has the old "42" in it, and gets the KeyError:

local#197778 2013-01-14_05:31:27.311038Z: all queries are retired, no extra servers: done
local#197779 2013-01-14_05:31:27.311780Z: servermap: 8*seq44-a3mv
local#197782 2013-01-14_05:31:27.312745Z: Retrieve(i2sen): starting
local#197783 2013-01-14_05:31:27.312889Z: got seqnum 42
local#197784 2013-01-14_05:31:27.585402Z: Unhandled Error
Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 800, in runUntilCurrent
    call.func(*call.args, **call.kw)
File "/home/occupy/allmydata-tahoe-1.9.2/support/lib/python2.7/site-packages/foolscap-0.6.4-py2.7.egg/foolscap/eventual.py", line 26, in _turn
    cb(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 368, in callback
    self._startRunCallbacks(result)
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 464, in _startRunCallbacks
    self._runCallbacks()
	--- <exception caught here> ---
File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 551, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 859, in <lambda>
    self._modify_once(modifier, first_time))
File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 885, in _modify_once
    d = self._try_to_download_data()
File "/home/occupy/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 "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 985, in _read
    d = r.download(consumer, offset, size)
File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 244, in download
    self._setup_download()
  File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 284, in _setup_download
    shares = versionmap[self.verinfo]
exceptions.KeyError: (42, "@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe", '4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2', 668, 666, 4, 8, "\x00\x00\x00\x00\x00\x00\x00\x00*@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2\x04\x08\x00\x00\x00\x00\x00\x00\x02\x9c\x00\x00\x00\x00\x00\x00\x02\x9a", (('enc_privkey', 956), ('EOF', 2172), ('share_data', 789), ('signature', 399), ('block_hash_tree', 757), ('share_hash_chain', 655)))
In [attachment:incident-2013-01-14--07-54-09Z-2ymyxfi.flog.bz2.dump.txt.manually-filtered.txt](/tahoe-lafs/trac/attachments/000078ac-7741-4e93-65b4-f65202501b87), you can see that the KeyError was preceded by a mysteriously changed version number, probably due to a different gateway modifying the directory at the same time as this gateway was doing so: ``` local#197564 2013-01-14_05:30:14.753657Z: found valid version 42-iatt from qenkbcot-sh3: 4-8/668/666 ``` … ``` local#197629 2013-01-14_05:30:18.187664Z: we are planning to push new seqnum=#43 ``` … ``` local#197655 2013-01-14_05:31:15.323720Z: our testv failed, so the write did not happen local#197656 2013-01-14_05:31:17.737595Z: somebody modified the share on us: shnum=3: I thought they had #42:R=iatt, but testv reported #44:R=ÙUQ$žÌJè)C⑍vDíŽ[·²±ºŒNE#˜ÖG\Ö local#197657 2013-01-14_05:31:17.737826Z: Publish failed with UncoordinatedWriteError ``` So then it does the automatic-merge-and-retry thing (which I would still like to remove, for simplicity): ``` local#197658 2013-01-14_05:31:21.260199Z: doing modify local#197659 2013-01-14_05:31:21.260870Z: SharemapUpdater(i2sen): starting (MODE_CHECK) ``` … ``` local#197745 2013-01-14_05:31:22.504839Z: got result from [qenkbcot], 1 shares local#197748 2013-01-14_05:31:22.509699Z: found valid version 44-a3mv from qenkbcot-sh3: 4-8/668/665 ``` But then it somehow uses a cached verinfo which has the old "42" in it, and gets the KeyError: ``` local#197778 2013-01-14_05:31:27.311038Z: all queries are retired, no extra servers: done local#197779 2013-01-14_05:31:27.311780Z: servermap: 8*seq44-a3mv local#197782 2013-01-14_05:31:27.312745Z: Retrieve(i2sen): starting local#197783 2013-01-14_05:31:27.312889Z: got seqnum 42 local#197784 2013-01-14_05:31:27.585402Z: Unhandled Error Traceback (most recent call last): File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 800, in runUntilCurrent call.func(*call.args, **call.kw) File "/home/occupy/allmydata-tahoe-1.9.2/support/lib/python2.7/site-packages/foolscap-0.6.4-py2.7.egg/foolscap/eventual.py", line 26, in _turn cb(*args, **kwargs) File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 368, in callback self._startRunCallbacks(result) File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 464, in _startRunCallbacks self._runCallbacks() --- <exception caught here> --- File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 551, in _runCallbacks current.result = callback(current.result, *args, **kw) File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 859, in <lambda> self._modify_once(modifier, first_time)) File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 885, in _modify_once d = self._try_to_download_data() File "/home/occupy/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 "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/filenode.py", line 985, in _read d = r.download(consumer, offset, size) File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 244, in download self._setup_download() File "/home/occupy/allmydata-tahoe-1.9.2/src/allmydata/mutable/retrieve.py", line 284, in _setup_download shares = versionmap[self.verinfo] exceptions.KeyError: (42, "@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe", '4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2', 668, 666, 4, 8, "\x00\x00\x00\x00\x00\x00\x00\x00*@'<F\x98\xbdY\xdf\x98\xc5\xa6\x885\xd7U\xe2\xb3U\x83\xdcn\xfa\x0fW2\xe7\xbc\xc1\\%r\xbe4\xeb\xc5- \x19\x8b)\xe1.@-z|\x1c\xb2\x04\x08\x00\x00\x00\x00\x00\x00\x02\x9c\x00\x00\x00\x00\x00\x00\x02\x9a", (('enc_privkey', 956), ('EOF', 2172), ('share_data', 789), ('signature', 399), ('block_hash_tree', 757), ('share_hash_chain', 655))) ```
zooko changed title from add tests for KeyError in mutable read-modify-write to KeyError in mutable read-modify-write 2013-01-14 09:54:38 +00:00

Replying to zooko:

News flash! joepie91 from IRC reported a bug which looks exactly like this one. However, he is using Tahoe-LAFS v1.9.2, with the patch from #1669 (changeset:5524/1.9.2) in place! This means that, contrary to what I thought, that patch did not fix this issue — #1670.

This is why tests are important. I'm always rather skeptical that something has been fixed if there is no test.

Replying to [zooko](/tahoe-lafs/trac/issues/1670#issuecomment-388693): > News flash! joepie91 from IRC reported a bug which looks exactly like this one. However, he is using Tahoe-LAFS v1.9.2, with the patch from #1669 (changeset:5524/1.9.2) in place! This means that, contrary to what I thought, that patch did not fix this issue — #1670. This is why tests are important. I'm always rather skeptical that something has been fixed if there is no test.

AF saw this bug -- it happened nondeterministically:

time tahoe cp /tmp/zeros-100m tahoe:zeros3
Error during PUT: 500 Internal Server Error
"Traceback (most recent call last):
  File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/base.py\", line 824, in runUntilCurrent
    call.func(*call.args, **call.kw)
  File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/foolscap-0.6.4-py2.7.egg/foolscap/eventual.py\", line 26, in _turn
    cb(*args, **kwargs)
  File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 380, in callback
    self._startRunCallbacks(result)
  File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 488, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 575, 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 284, in _setup_download
    shares = versionmap[self.verinfo]
exceptions.KeyError: (9, '\\x9b\\xb9\\xaa\\xa5\\xfa\\x88\\x9bX\\x03\\x99HK\\x06\\xed\\xa5V\\x12\\xd6f\\x97l^\\x9f\\x06\\x98\\xac\\xe7\\xb4\\xcdn\\x82\\xa8', 'V\\x97\\x15\\\\\\xf8[7\\rZ\\x9bZ\\xf1\\x93\\xe2\\xdb\\xc2', 2145, 2144, 3, 10, '\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\t\\x9b\\xb9\\xaa\\xa5\\xfa\\x88\\x9bX\\x03\\x99HK\\x06\\xed\\xa5V\\x12\\xd6f\\x97l^\\x9f\\x06\\x98\\xac\\xe7\\xb4\\xcdn\\x82\\xa8V\\x97\\x15\\\\\\xf8[7\\rZ\\x9bZ\\xf1\\x93\\xe2\\xdb\\xc2\\x03\\n\\x00\\x00\\x00\\x00\\x00\\x00\\x08a\\x00\\x00\\x00\\x00\\x00\\x00\\x08\`', (('enc_privkey', 1538), ('EOF', 2753), ('share_data', 823), ('signature', 399), ('block_hash_tree', 791), ('share_hash_chain', 655)))
"

(Presumably it is happening on the update of the tahoe:zeros3 directory.)

Notice that this is using Tahoe-LAFS v1.10.

AF saw this bug -- it happened nondeterministically: ``` time tahoe cp /tmp/zeros-100m tahoe:zeros3 Error during PUT: 500 Internal Server Error "Traceback (most recent call last): File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/base.py\", line 824, in runUntilCurrent call.func(*call.args, **call.kw) File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/foolscap-0.6.4-py2.7.egg/foolscap/eventual.py\", line 26, in _turn cb(*args, **kwargs) File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 380, in callback self._startRunCallbacks(result) File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 488, in _startRunCallbacks self._runCallbacks() --- <exception caught here> --- File \"/root/allmydata-tahoe-1.10.0/support/lib/python2.7/site-packages/Twisted-13.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py\", line 575, 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 284, in _setup_download shares = versionmap[self.verinfo] exceptions.KeyError: (9, '\\x9b\\xb9\\xaa\\xa5\\xfa\\x88\\x9bX\\x03\\x99HK\\x06\\xed\\xa5V\\x12\\xd6f\\x97l^\\x9f\\x06\\x98\\xac\\xe7\\xb4\\xcdn\\x82\\xa8', 'V\\x97\\x15\\\\\\xf8[7\\rZ\\x9bZ\\xf1\\x93\\xe2\\xdb\\xc2', 2145, 2144, 3, 10, '\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\t\\x9b\\xb9\\xaa\\xa5\\xfa\\x88\\x9bX\\x03\\x99HK\\x06\\xed\\xa5V\\x12\\xd6f\\x97l^\\x9f\\x06\\x98\\xac\\xe7\\xb4\\xcdn\\x82\\xa8V\\x97\\x15\\\\\\xf8[7\\rZ\\x9bZ\\xf1\\x93\\xe2\\xdb\\xc2\\x03\\n\\x00\\x00\\x00\\x00\\x00\\x00\\x08a\\x00\\x00\\x00\\x00\\x00\\x00\\x08\`', (('enc_privkey', 1538), ('EOF', 2753), ('share_data', 823), ('signature', 399), ('block_hash_tree', 791), ('share_hash_chain', 655))) " ``` (Presumably it is happening on the update of the `tahoe:zeros3` directory.) Notice that this is using Tahoe-LAFS v1.10.

Ed Kapitein posted to the tahoe-dev list [//pipermail/tahoe-dev/2013-July/008487.html a bug report] that matches this stack trace.

Ed Kapitein posted to the tahoe-dev list [//pipermail/tahoe-dev/2013-July/008487.html a bug report] that matches this stack trace.

Upgrading "Priority" from "normal" to "major", because this seems like a bad bug. It also apparently led to data loss in Ed Kapitein's case, so I'm adding the preservation keyword.

Upgrading "Priority" from "normal" to "major", because this seems like a bad bug. It also apparently led to data loss in Ed Kapitein's case, so I'm adding the `preservation` keyword.
zooko added
p/major
and removed
p/normal
labels 2013-07-05 17:00:58 +00:00

Replying to kevan:

It looks like the mutable filenode modification code in MutableFileVersion reacts to an UncoordinatedWriteError by performing a map update, then trying the operation again. That map update will update the MutableFileVersion's internal servermap, but not its internal verinfo tuple. If the UncoordinatedWriteError is due to a concurrent update operation that updated all or most (enough for the version to be unrecoverable, anyway) of the shares associated with the MutableFileVersion's version of the mutable file, then we would see the KeyError reported by vikarti and others.

So, isn't the correct fix for this, without making any design changes, just for MutableFileVersion to make sure that its verinfo tuple is also updated when it does a mapupdate in this case?

Replying to [kevan](/tahoe-lafs/trac/issues/1670#issuecomment-388664): > It looks like the mutable filenode modification code in `MutableFileVersion` reacts to an `UncoordinatedWriteError` by performing a map update, then trying the operation again. That map update will update the `MutableFileVersion`'s internal servermap, but not its internal verinfo tuple. If the `UncoordinatedWriteError` is due to a concurrent update operation that updated all or most (enough for the version to be unrecoverable, anyway) of the shares associated with the `MutableFileVersion`'s version of the mutable file, then we would see the `KeyError` reported by vikarti and others. So, isn't the correct fix for this, without making any design changes, just for `MutableFileVersion` to make sure that its verinfo tuple is also updated when it does a mapupdate in this case?
zooko modified the milestone from soon to 1.11.0 2013-08-28 15:36:41 +00:00
zooko added
p/critical
and removed
p/major
labels 2013-10-31 15:50:46 +00:00

We investigated this during the Tahoe-LAFS Summit. It seems likely that directory-modification operations have been accidentally using the original version of the directory, even when there was a write-collision and a newer version of the directory was discovered. I didn't 100% confirm this, but I suspect that means that in those (rare‽) cases where there are write-collisions on a directory, the retrying code would blow away the other person's write, by re-applying the earlier version (plus the current modification). This would be a data loss bug and very much not the kind of thing we tolerate. ☹

Now, there are no bug reports that I am aware of that could point to this having caused a directory modification to get thrown out in practice. There are several reports of this bug leading to an internal KeyError, but as far as I recall, nobody reported that a change they had made to their directory was subsequently discovered to have been lost.

Nonetheless, the possibility of this happening seems to be present, from code inspection.

We investigated this during the Tahoe-LAFS Summit. It seems likely that directory-modification operations have been accidentally using the original version of the directory, even when there was a write-collision and a newer version of the directory was discovered. I didn't 100% confirm this, but I suspect that means that in those (rare‽) cases where there are write-collisions on a directory, the retrying code would blow away the other person's write, by re-applying the earlier version (plus the current modification). This would be a data loss bug and very much not the kind of thing we tolerate. ☹ Now, there are *no* bug reports that I am aware of that could point to this having caused a directory modification to get thrown out in practice. There are several reports of this bug leading to an internal `KeyError`, but as far as I recall, nobody reported that a change they had made to their directory was subsequently discovered to have been lost. Nonetheless, the possibility of this happening seems to be present, from code inspection.

We agreed at the Tahoe-LAFS Summit to remove the "retry" feature instead of fixing it, for v1.11.0. I have a branch which does this: https://github.com/zooko/tahoe-lafs/commits/1670-KeyError-in-mutable-read-modify-write

This branch is not yet ready to merge into trunk because:

• Although it has unit tests, I'm not yet sure they are correct tests.

• The history of patches needs to be rewritten into a nice readable story.

We agreed at the Tahoe-LAFS Summit to remove the "retry" feature instead of fixing it, for v1.11.0. I have a branch which does this: <https://github.com/zooko/tahoe-lafs/commits/1670-KeyError-in-mutable-read-modify-write> This branch is not yet ready to merge into trunk because: • Although it has unit tests, I'm not yet sure they are *correct* tests. • The history of patches needs to be rewritten into a nice readable story.
daira modified the milestone from 1.11.0 to 1.12.0 2014-09-02 16:20:17 +00:00

We have no fix for this, nor do we understand it well.

We have no fix for this, nor do we understand it well.

Milestone renamed

Milestone renamed
warner modified the milestone from 1.12.0 to 1.13.0 2016-03-22 05:02:25 +00:00

renaming milestone

renaming milestone
warner modified the milestone from 1.13.0 to 1.14.0 2016-06-28 18:17:14 +00:00

Moving open issues out of closed milestones.

Moving open issues out of closed milestones.
exarkun modified the milestone from 1.14.0 to 1.15.0 2020-06-30 14:45:13 +00:00

Ticket retargeted after milestone closed

Ticket retargeted after milestone closed
meejah modified the milestone from 1.15.0 to soon 2021-03-30 18:40:19 +00:00
Sign in to join this conversation.
No labels
c/code
c/code-dirnodes
c/code-encoding
c/code-frontend
c/code-frontend-cli
c/code-frontend-ftp-sftp
c/code-frontend-magic-folder
c/code-frontend-web
c/code-mutable
c/code-network
c/code-nodeadmin
c/code-peerselection
c/code-storage
c/contrib
c/dev-infrastructure
c/docs
c/operational
c/packaging
c/unknown
c/website
kw:2pc
kw:410
kw:9p
kw:ActivePerl
kw:AttributeError
kw:DataUnavailable
kw:DeadReferenceError
kw:DoS
kw:FileZilla
kw:GetLastError
kw:IFinishableConsumer
kw:K
kw:LeastAuthority
kw:Makefile
kw:RIStorageServer
kw:StringIO
kw:UncoordinatedWriteError
kw:about
kw:access
kw:access-control
kw:accessibility
kw:accounting
kw:accounting-crawler
kw:add-only
kw:aes
kw:aesthetics
kw:alias
kw:aliases
kw:aliens
kw:allmydata
kw:amazon
kw:ambient
kw:annotations
kw:anonymity
kw:anonymous
kw:anti-censorship
kw:api_auth_token
kw:appearance
kw:appname
kw:apport
kw:archive
kw:archlinux
kw:argparse
kw:arm
kw:assertion
kw:attachment
kw:auth
kw:authentication
kw:automation
kw:avahi
kw:availability
kw:aws
kw:azure
kw:backend
kw:backoff
kw:backup
kw:backupdb
kw:backward-compatibility
kw:bandwidth
kw:basedir
kw:bayes
kw:bbfreeze
kw:beta
kw:binaries
kw:binutils
kw:bitcoin
kw:bitrot
kw:blacklist
kw:blocker
kw:blocks-cloud-deployment
kw:blocks-cloud-merge
kw:blocks-magic-folder-merge
kw:blocks-merge
kw:blocks-raic
kw:blocks-release
kw:blog
kw:bom
kw:bonjour
kw:branch
kw:branding
kw:breadcrumbs
kw:brians-opinion-needed
kw:browser
kw:bsd
kw:build
kw:build-helpers
kw:buildbot
kw:builders
kw:buildslave
kw:buildslaves
kw:cache
kw:cap
kw:capleak
kw:captcha
kw:cast
kw:centos
kw:cffi
kw:chacha
kw:charset
kw:check
kw:checker
kw:chroot
kw:ci
kw:clean
kw:cleanup
kw:cli
kw:cloud
kw:cloud-backend
kw:cmdline
kw:code
kw:code-checks
kw:coding-standards
kw:coding-tools
kw:coding_tools
kw:collection
kw:compatibility
kw:completion
kw:compression
kw:confidentiality
kw:config
kw:configuration
kw:configuration.txt
kw:conflict
kw:connection
kw:connectivity
kw:consistency
kw:content
kw:control
kw:control.furl
kw:convergence
kw:coordination
kw:copyright
kw:corruption
kw:cors
kw:cost
kw:coverage
kw:coveralls
kw:coveralls.io
kw:cpu-watcher
kw:cpyext
kw:crash
kw:crawler
kw:crawlers
kw:create-container
kw:cruft
kw:crypto
kw:cryptography
kw:cryptography-lib
kw:cryptopp
kw:csp
kw:curl
kw:cutoff-date
kw:cycle
kw:cygwin
kw:d3
kw:daemon
kw:darcs
kw:darcsver
kw:database
kw:dataloss
kw:db
kw:dead-code
kw:deb
kw:debian
kw:debug
kw:deep-check
kw:defaults
kw:deferred
kw:delete
kw:deletion
kw:denial-of-service
kw:dependency
kw:deployment
kw:deprecation
kw:desert-island
kw:desert-island-build
kw:design
kw:design-review-needed
kw:detection
kw:dev-infrastructure
kw:devpay
kw:directory
kw:directory-page
kw:dirnode
kw:dirnodes
kw:disconnect
kw:discovery
kw:disk
kw:disk-backend
kw:distribute
kw:distutils
kw:dns
kw:do_http
kw:doc-needed
kw:docker
kw:docs
kw:docs-needed
kw:dokan
kw:dos
kw:download
kw:downloader
kw:dragonfly
kw:drop-upload
kw:duplicity
kw:dusty
kw:earth-dragon
kw:easy
kw:ec2
kw:ecdsa
kw:ed25519
kw:egg-needed
kw:eggs
kw:eliot
kw:email
kw:empty
kw:encoding
kw:endpoint
kw:enterprise
kw:enum34
kw:environment
kw:erasure
kw:erasure-coding
kw:error
kw:escaping
kw:etag
kw:etch
kw:evangelism
kw:eventual
kw:example
kw:excess-authority
kw:exec
kw:exocet
kw:expiration
kw:extensibility
kw:extension
kw:failure
kw:fedora
kw:ffp
kw:fhs
kw:figleaf
kw:file
kw:file-descriptor
kw:filename
kw:filesystem
kw:fileutil
kw:fips
kw:firewall
kw:first
kw:floatingpoint
kw:flog
kw:foolscap
kw:forward-compatibility
kw:forward-secrecy
kw:forwarding
kw:free
kw:freebsd
kw:frontend
kw:fsevents
kw:ftp
kw:ftpd
kw:full
kw:furl
kw:fuse
kw:garbage
kw:garbage-collection
kw:gateway
kw:gatherer
kw:gc
kw:gcc
kw:gentoo
kw:get
kw:git
kw:git-annex
kw:github
kw:glacier
kw:globalcaps
kw:glossary
kw:google-cloud-storage
kw:google-drive-backend
kw:gossip
kw:governance
kw:grid
kw:grid-manager
kw:gridid
kw:gridsync
kw:grsec
kw:gsoc
kw:gvfs
kw:hackfest
kw:hacktahoe
kw:hang
kw:hardlink
kw:heartbleed
kw:heisenbug
kw:help
kw:helper
kw:hint
kw:hooks
kw:how
kw:how-to
kw:howto
kw:hp
kw:hp-cloud
kw:html
kw:http
kw:https
kw:i18n
kw:i2p
kw:i2p-collab
kw:illustration
kw:image
kw:immutable
kw:impressions
kw:incentives
kw:incident
kw:init
kw:inlineCallbacks
kw:inotify
kw:install
kw:installer
kw:integration
kw:integration-test
kw:integrity
kw:interactive
kw:interface
kw:interfaces
kw:interoperability
kw:interstellar-exploration
kw:introducer
kw:introduction
kw:iphone
kw:ipkg
kw:iputil
kw:ipv6
kw:irc
kw:jail
kw:javascript
kw:joke
kw:jquery
kw:json
kw:jsui
kw:junk
kw:key-value-store
kw:kfreebsd
kw:known-issue
kw:konqueror
kw:kpreid
kw:kvm
kw:l10n
kw:lae
kw:large
kw:latency
kw:leak
kw:leasedb
kw:leases
kw:libgmp
kw:license
kw:licenss
kw:linecount
kw:link
kw:linux
kw:lit
kw:localhost
kw:location
kw:locking
kw:logging
kw:logo
kw:loopback
kw:lucid
kw:mac
kw:macintosh
kw:magic-folder
kw:manhole
kw:manifest
kw:manual-test-needed
kw:map
kw:mapupdate
kw:max_space
kw:mdmf
kw:memcheck
kw:memory
kw:memory-leak
kw:mesh
kw:metadata
kw:meter
kw:migration
kw:mime
kw:mingw
kw:minimal
kw:misc
kw:miscapture
kw:mlp
kw:mock
kw:more-info-needed
kw:mountain-lion
kw:move
kw:multi-users
kw:multiple
kw:multiuser-gateway
kw:munin
kw:music
kw:mutability
kw:mutable
kw:mystery
kw:names
kw:naming
kw:nas
kw:navigation
kw:needs-review
kw:needs-spawn
kw:netbsd
kw:network
kw:nevow
kw:new-user
kw:newcaps
kw:news
kw:news-done
kw:news-needed
kw:newsletter
kw:newurls
kw:nfc
kw:nginx
kw:nixos
kw:no-clobber
kw:node
kw:node-url
kw:notification
kw:notifyOnDisconnect
kw:nsa310
kw:nsa320
kw:nsa325
kw:numpy
kw:objects
kw:old
kw:openbsd
kw:openitp-packaging
kw:openssl
kw:openstack
kw:opensuse
kw:operation-helpers
kw:operational
kw:operations
kw:ophandle
kw:ophandles
kw:ops
kw:optimization
kw:optional
kw:options
kw:organization
kw:os
kw:os.abort
kw:ostrom
kw:osx
kw:osxfuse
kw:otf-magic-folder-objective1
kw:otf-magic-folder-objective2
kw:otf-magic-folder-objective3
kw:otf-magic-folder-objective4
kw:otf-magic-folder-objective5
kw:otf-magic-folder-objective6
kw:p2p
kw:packaging
kw:partial
kw:password
kw:path
kw:paths
kw:pause
kw:peer-selection
kw:performance
kw:permalink
kw:permissions
kw:persistence
kw:phone
kw:pickle
kw:pip
kw:pipermail
kw:pkg_resources
kw:placement
kw:planning
kw:policy
kw:port
kw:portability
kw:portal
kw:posthook
kw:pratchett
kw:preformance
kw:preservation
kw:privacy
kw:process
kw:profile
kw:profiling
kw:progress
kw:proxy
kw:publish
kw:pyOpenSSL
kw:pyasn1
kw:pycparser
kw:pycrypto
kw:pycrypto-lib
kw:pycryptopp
kw:pyfilesystem
kw:pyflakes
kw:pylint
kw:pypi
kw:pypy
kw:pysqlite
kw:python
kw:python3
kw:pythonpath
kw:pyutil
kw:pywin32
kw:quickstart
kw:quiet
kw:quotas
kw:quoting
kw:raic
kw:rainhill
kw:random
kw:random-access
kw:range
kw:raspberry-pi
kw:reactor
kw:readonly
kw:rebalancing
kw:recovery
kw:recursive
kw:redhat
kw:redirect
kw:redressing
kw:refactor
kw:referer
kw:referrer
kw:regression
kw:rekey
kw:relay
kw:release
kw:release-blocker
kw:reliability
kw:relnotes
kw:remote
kw:removable
kw:removable-disk
kw:rename
kw:renew
kw:repair
kw:replace
kw:report
kw:repository
kw:research
kw:reserved_space
kw:response-needed
kw:response-time
kw:restore
kw:retrieve
kw:retry
kw:review
kw:review-needed
kw:reviewed
kw:revocation
kw:roadmap
kw:rollback
kw:rpm
kw:rsa
kw:rss
kw:rst
kw:rsync
kw:rusty
kw:s3
kw:s3-backend
kw:s3-frontend
kw:s4
kw:same-origin
kw:sandbox
kw:scalability
kw:scaling
kw:scheduling
kw:schema
kw:scheme
kw:scp
kw:scripts
kw:sdist
kw:sdmf
kw:security
kw:self-contained
kw:server
kw:servermap
kw:servers-of-happiness
kw:service
kw:setup
kw:setup.py
kw:setup_requires
kw:setuptools
kw:setuptools_darcs
kw:sftp
kw:shared
kw:shareset
kw:shell
kw:signals
kw:simultaneous
kw:six
kw:size
kw:slackware
kw:slashes
kw:smb
kw:sneakernet
kw:snowleopard
kw:socket
kw:solaris
kw:space
kw:space-efficiency
kw:spam
kw:spec
kw:speed
kw:sqlite
kw:ssh
kw:ssh-keygen
kw:sshfs
kw:ssl
kw:stability
kw:standards
kw:start
kw:startup
kw:static
kw:static-analysis
kw:statistics
kw:stats
kw:stats_gatherer
kw:status
kw:stdeb
kw:storage
kw:streaming
kw:strports
kw:style
kw:stylesheet
kw:subprocess
kw:sumo
kw:survey
kw:svg
kw:symlink
kw:synchronous
kw:tac
kw:tahoe-*
kw:tahoe-add-alias
kw:tahoe-admin
kw:tahoe-archive
kw:tahoe-backup
kw:tahoe-check
kw:tahoe-cp
kw:tahoe-create-alias
kw:tahoe-create-introducer
kw:tahoe-debug
kw:tahoe-deep-check
kw:tahoe-deepcheck
kw:tahoe-lafs-trac-stream
kw:tahoe-list-aliases
kw:tahoe-ls
kw:tahoe-magic-folder
kw:tahoe-manifest
kw:tahoe-mkdir
kw:tahoe-mount
kw:tahoe-mv
kw:tahoe-put
kw:tahoe-restart
kw:tahoe-rm
kw:tahoe-run
kw:tahoe-start
kw:tahoe-stats
kw:tahoe-unlink
kw:tahoe-webopen
kw:tahoe.css
kw:tahoe_files
kw:tahoewapi
kw:tarball
kw:tarballs
kw:tempfile
kw:templates
kw:terminology
kw:test
kw:test-and-set
kw:test-from-egg
kw:test-needed
kw:testgrid
kw:testing
kw:tests
kw:throttling
kw:ticket999-s3-backend
kw:tiddly
kw:time
kw:timeout
kw:timing
kw:to
kw:to-be-closed-on-2011-08-01
kw:tor
kw:tor-protocol
kw:torsocks
kw:tox
kw:trac
kw:transparency
kw:travis
kw:travis-ci
kw:trial
kw:trickle
kw:trivial
kw:truckee
kw:tub
kw:tub.location
kw:twine
kw:twistd
kw:twistd.log
kw:twisted
kw:twisted-14
kw:twisted-trial
kw:twitter
kw:twn
kw:txaws
kw:type
kw:typeerror
kw:ubuntu
kw:ucwe
kw:ueb
kw:ui
kw:unclean
kw:uncoordinated-writes
kw:undeletable
kw:unfinished-business
kw:unhandled-error
kw:unhappy
kw:unicode
kw:unit
kw:unix
kw:unlink
kw:update
kw:upgrade
kw:upload
kw:upload-helper
kw:uri
kw:url
kw:usability
kw:use-case
kw:utf-8
kw:util
kw:uwsgi
kw:ux
kw:validation
kw:variables
kw:vdrive
kw:verify
kw:verlib
kw:version
kw:versioning
kw:versions
kw:video
kw:virtualbox
kw:virtualenv
kw:vista
kw:visualization
kw:visualizer
kw:vm
kw:volunteergrid2
kw:volunteers
kw:vpn
kw:wapi
kw:warners-opinion-needed
kw:warning
kw:weapi
kw:web
kw:web.port
kw:webapi
kw:webdav
kw:webdrive
kw:webport
kw:websec
kw:website
kw:websocket
kw:welcome
kw:welcome-page
kw:welcomepage
kw:wiki
kw:win32
kw:win64
kw:windows
kw:windows-related
kw:winscp
kw:workaround
kw:world-domination
kw:wrapper
kw:write-enabler
kw:wui
kw:x86
kw:x86-64
kw:xhtml
kw:xml
kw:xss
kw:zbase32
kw:zetuptoolz
kw:zfec
kw:zookos-opinion-needed
kw:zope
kw:zope.interface
p/blocker
p/critical
p/major
p/minor
p/normal
p/supercritical
p/trivial
r/cannot reproduce
r/duplicate
r/fixed
r/invalid
r/somebody else's problem
r/was already fixed
r/wontfix
r/worksforme
t/defect
t/enhancement
t/task
v/0.2.0
v/0.3.0
v/0.4.0
v/0.5.0
v/0.5.1
v/0.6.0
v/0.6.1
v/0.7.0
v/0.8.0
v/0.9.0
v/1.0.0
v/1.1.0
v/1.10.0
v/1.10.1
v/1.10.2
v/1.10a2
v/1.11.0
v/1.12.0
v/1.12.1
v/1.13.0
v/1.14.0
v/1.15.0
v/1.15.1
v/1.2.0
v/1.3.0
v/1.4.1
v/1.5.0
v/1.6.0
v/1.6.1
v/1.7.0
v/1.7.1
v/1.7β
v/1.8.0
v/1.8.1
v/1.8.2
v/1.8.3
v/1.8β
v/1.9.0
v/1.9.0-s3branch
v/1.9.0a1
v/1.9.0a2
v/1.9.0b1
v/1.9.1
v/1.9.2
v/1.9.2a1
v/cloud-branch
v/unknown
No milestone
No project
No assignees
6 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: tahoe-lafs/trac#1670
No description provided.