[tahoe-lafs-trac-stream] [tahoe-lafs] #1670: add tests for KeyError in mutable read-modify-write

[tahoe-lafs]

#1670: add tests for KeyError in mutable read-modify-write
-------------------------+-------------------------------------------------
     Reporter:  vikarti  |      Owner:  zooko
         Type:  defect   |     Status:  assigned
     Priority:  normal   |  Milestone:  1.11.0
    Component:  code-    |    Version:  1.9.1
  mutable                |   Keywords:  mutable retrieve error tahoe-backup
   Resolution:           |  regression test-needed
Launchpad Bug:           |
-------------------------+-------------------------------------------------

Comment (by zooko):

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

-- 
Ticket URL: <https://tahoe-lafs.org/trac/tahoe-lafs/ticket/1670#comment:35>
tahoe-lafs <https://tahoe-lafs.org>
secure decentralized storage