tahoe-lafs/trac

Multiples storage servers can be registered with the same FURL (UncoordinatedWriteError on I2P grid) #2875

New issue

Open

opened 2017-06-03 09:32:12 +00:00 by nwks · 7 comments

nwks commented

2017-06-03 09:32:12 +00:00

Owner

On the I2P grid, introducers send announcements with different key_s but with the same FURL (#2887).

As NativeStorageServer.get_serverid() returns key_s, it is possible for StorageFarmBroker to register these announcements as separate storage servers. So when publishing, share writers can end up writing to the same destination and then find surprise shares, triggering a UncoordinatedWriteError.

In release 1.11, _tubid was used in get_serverid() instead of key_s, so this issue did not exist. Also it is not yet widespread on the I2P grid as most nodes are still running 1.10.

Workaround: check for duplicated FURLs in NativeStorageServer announcement processing, or restore the return value of NativeStorageServer.get_serverid() to _tubid, instead of key_s.

Original description

I've setup a node on the I2P grid which has ~30 storage server connected.
However I am unable to create aliases or directories with the default setting (SDMF) as it always fails with an UncoordinatedWriteError.

> tahoe create-alias newalias
Error during HTTP request: 500 Internal Server Error
Traceback (most recent call last):
Failure: allmydata.mutable.common.UncoordinatedWriteError:

 > tahoe mkdir tahoe:newdir
Error during HTTP request: 500 Internal Server Error
Traceback (most recent call last):
Failure: allmydata.mutable.common.UncoordinatedWriteError:

Here is a flog dump when it happens (flogs are also attached):

Remote Versions:
 Nevow: 0.14.2
 OpenSSL: 1.0.1t
 PyYAML: 3.12
 Twisted: 17.1.0
 appdirs: 1.4.3
 asn1crypto: 0.22.0
 attrs: 17.1.0
 automat: 0.6.0
 cffi: 1.10.0
 characteristic: 14.3.0
 constantly: 15.1.0
 cryptography: 1.8.1
 enum34: 1.1.6
 foolscap: 0.12.6
 idna: 2.5
 incremental: 16.10.1
 ipaddress: 1.0.18
 packaging: 16.8
 platform: Linux-debian_8.8-x86_64-64bit_ELF
 pyOpenSSL: 17.0.0
 pyasn1: 0.2.3
 pyasn1-modules: 0.0.8
 pycparser: 2.17
 pycrypto: 2.6.1
 pycryptopp: 0.7.1.869544967005693312591928092448767568728501330214
 pyparsing: 2.2.0
 python: 2.7.9
 service-identity: 16.0.0
 setuptools: 35.0.2
 simplejson: 3.10.0
 six: 1.10.0
 tahoe-lafs: 1.12.1
 twisted: 17.1.0
 zfec: 1.4.24
 zope.interface: unknown
08:19:43.855 L20 []#172995 Publish(iarly): starting
08:19:43.855 L20 []#172996 starting publish, datalen is 0
08:19:43.856 L10 []#172997 new seqnum will be 1
08:19:43.857 L20 []#172998 building encoding parameters for file
08:19:43.857 L20 []#172999 got segsize 0
08:19:43.857 L20 []#173000 got 0 segments
08:19:43.857 L20 []#173001 got start segment 0
08:19:43.857 L20 []#173002 got end segment -1
08:19:43.857 L10 []#173003 current goal: before update:
08:19:43.857 L10 []#173004 we are planning to push new seqnum=#1
08:19:43.857 L10 []#173005 current goal: after update: , sh0 to [3cqfcfch], sh1 to [ysse5rzw], sh2 to [vl3r33qr], sh3 to [xazwtxob], sh4 to [t6b4wzcs], sh5 to [6i2sk6xm], sh6 to [wbaqeiex], sh7 to [qlnepnf6], sh8 to [svq7zfma], sh9 to [55khl43t]
08:19:43.857 L10 []#173006 we are planning to push new seqnum=#1
08:19:43.859 L20 []#173007 Starting push
08:19:44.306 L20 []#173008 storage: slot_writev iarlyicewprjrxlabf5pvsgaiu
08:19:44.320 L20 []#173009 _got_write_answer from 3cqfcfch, share 0
08:19:44.320 L20 []#173010 found the following surprise shares: set([])
08:19:44.321 L20 []#173011 wrote successfully: adding new share to servermap
08:19:44.864 L20 []#173012 _got_write_answer from qlnepnf6, share 7
08:19:44.864 L20 []#173013 found the following surprise shares: set([])
08:19:44.864 L20 []#173014 wrote successfully: adding new share to servermap
08:19:45.097 L20 []#173015 _got_write_answer from svq7zfma, share 8
08:19:45.097 L20 []#173016 found the following surprise shares: set([7])
08:19:45.098 L30 []#173017 they had shares [7] that we didn't know about
08:19:46.178 L20 []#173018 wrote successfully: adding new share to servermap
08:19:46.194 L20 []#173019 _got_write_answer from 6i2sk6xm, share 5
08:19:46.194 L20 []#173020 found the following surprise shares: set([])
08:19:46.194 L20 []#173021 wrote successfully: adding new share to servermap
08:19:46.208 L20 []#173022 _got_write_answer from 55khl43t, share 9
08:19:46.208 L20 []#173023 found the following surprise shares: set([])
08:19:46.208 L20 []#173024 wrote successfully: adding new share to servermap
08:19:46.877 L20 []#173025 _got_write_answer from ysse5rzw, share 1
08:19:46.878 L20 []#173026 found the following surprise shares: set([])
08:19:46.878 L20 []#173027 wrote successfully: adding new share to servermap
08:19:47.432 L20 []#173028 _got_write_answer from vl3r33qr, share 2
08:19:47.432 L20 []#173029 found the following surprise shares: set([1])
08:19:47.432 L30 []#173030 they had shares [1] that we didn't know about
08:19:47.433 L20 []#173031 wrote successfully: adding new share to servermap
08:19:47.641 L20 []#173032 _got_write_answer from wbaqeiex, share 6
08:19:47.641 L20 []#173033 found the following surprise shares: set([5])
08:19:47.641 L30 []#173034 they had shares [5] that we didn't know about
08:19:47.641 L20 []#173035 wrote successfully: adding new share to servermap
08:19:51.945 L20 []#173036 _got_write_answer from xazwtxob, share 3
08:19:51.945 L20 []#173037 found the following surprise shares: set([])
08:19:51.945 L20 []#173038 wrote successfully: adding new share to servermap
08:19:55.978 L20 []#173039 _got_write_answer from t6b4wzcs, share 4
08:19:55.978 L20 []#173040 found the following surprise shares: set([3])
08:19:55.978 L30 []#173041 they had shares [3] that we didn't know about
08:19:57.085 L20 []#173042 wrote successfully: adding new share to servermap
08:19:57.086 L20 []#173043 Publish failed with UncoordinatedWriteError
08:19:57.106 L20 []#173044 web: 127.0.0.1 POST /uri/[CENSORED]..?t=mkdir 500 95

Creating MDMF files or directories in the WUI, and un-linking throws the following KeyError, but the job actually gets done.
(I manually created the tahoe: alias that way.)

 > tahoe rm tahoe:testfile
ERROR: 500 Internal Server Error
"Traceback (most recent call last):
  File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/base.py\", line 878, in runUntilCurrent
    call.func(*call.args, **call.kw)
  File \"/home/debian/.local/lib/python2.7/site-packages/foolscap/eventual.py\", line 26, in _turn
    cb(*args, **kwargs)
  File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 459, in callback
    self._startRunCallbacks(result)
  File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 567, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 653, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 856, in _retry
    f.trap(UncoordinatedWriteError)
  File \"/home/debian/.local/lib/python2.7/site-packages/twisted/python/failure.py\", line 346, in trap
    self.raiseException()
  File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 653, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 854, in <lambda>
    self._modify_once(modifier, first_time))
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 880, in _modify_once
    d = self._try_to_download_data()
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 958, in _try_to_download_data
    d = self._read(c, fetch_privkey=True)
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 980, in _read
    d = r.download(consumer, offset, size)
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 253, in download
    self._start_download(consumer, offset, size)
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 265, in _start_download
    self._setup_download()
  File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 301, in _setup_download
    shares = versionmap[self.verinfo]
exceptions.KeyError: (12, \"\\x9f\\x02FDS5O\\xed\\x1fEz\\xa2\\x02\\xd1\\x97\\xb9%\\x0b\\xef\\xc2{\\xa6\\xcc\\x0b'&\\xf3]\\x9c\\x8e\\x05\\xa7\", None, 131073, 1108, 3, 10, \"\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x0c\\x9f\\x02FDS5O\\xed\\x1fEz\\xa2\\x02\\xd1\\x97\\xb9%\\x0b\\xef\\xc2{\\xa6\\xcc\\x0b'&\\xf3]\\x9c\\x8e\\x05\\xa7\\x03\\n\\x00\\x00\\x00\\x00\\x00\\x02\\x00\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x04T\", (('EOF', 2585), ('verification_key', 1731), ('enc_privkey', 123), ('share_data', 2167), ('signature', 1475), ('block_hash_tree', 2553), ('share_hash_chain', 1339), ('verification_key_end', 2023)))

I had no issues on the testGrid.

On the I2P grid, introducers send announcements with different key_s but with the same FURL (#2887). As *NativeStorageServer.get_serverid()* returns key_s, it is possible for *StorageFarmBroker* to register these announcements as separate storage servers. So when publishing, share writers can end up writing to the same destination and then find surprise shares, triggering a UncoordinatedWriteError. In release 1.11, *_tubid* was used in *get_serverid()* instead of *key_s*, so this issue did not exist. Also it is not yet widespread on the I2P grid as most nodes are still running 1.10. Workaround: check for duplicated FURLs in *NativeStorageServer* announcement processing, or restore the return value of *NativeStorageServer.get_serverid()* to *_tubid*, instead of *key_s*. ## Original description I've setup a node on the I2P grid which has ~30 storage server connected. However I am unable to create aliases or directories with the default setting (SDMF) as it always fails with an UncoordinatedWriteError. ``` > tahoe create-alias newalias Error during HTTP request: 500 Internal Server Error Traceback (most recent call last): Failure: allmydata.mutable.common.UncoordinatedWriteError: > tahoe mkdir tahoe:newdir Error during HTTP request: 500 Internal Server Error Traceback (most recent call last): Failure: allmydata.mutable.common.UncoordinatedWriteError: ``` Here is a flog dump when it happens (flogs are also attached): ``` Remote Versions: Nevow: 0.14.2 OpenSSL: 1.0.1t PyYAML: 3.12 Twisted: 17.1.0 appdirs: 1.4.3 asn1crypto: 0.22.0 attrs: 17.1.0 automat: 0.6.0 cffi: 1.10.0 characteristic: 14.3.0 constantly: 15.1.0 cryptography: 1.8.1 enum34: 1.1.6 foolscap: 0.12.6 idna: 2.5 incremental: 16.10.1 ipaddress: 1.0.18 packaging: 16.8 platform: Linux-debian_8.8-x86_64-64bit_ELF pyOpenSSL: 17.0.0 pyasn1: 0.2.3 pyasn1-modules: 0.0.8 pycparser: 2.17 pycrypto: 2.6.1 pycryptopp: 0.7.1.869544967005693312591928092448767568728501330214 pyparsing: 2.2.0 python: 2.7.9 service-identity: 16.0.0 setuptools: 35.0.2 simplejson: 3.10.0 six: 1.10.0 tahoe-lafs: 1.12.1 twisted: 17.1.0 zfec: 1.4.24 zope.interface: unknown 08:19:43.855 L20 []#172995 Publish(iarly): starting 08:19:43.855 L20 []#172996 starting publish, datalen is 0 08:19:43.856 L10 []#172997 new seqnum will be 1 08:19:43.857 L20 []#172998 building encoding parameters for file 08:19:43.857 L20 []#172999 got segsize 0 08:19:43.857 L20 []#173000 got 0 segments 08:19:43.857 L20 []#173001 got start segment 0 08:19:43.857 L20 []#173002 got end segment -1 08:19:43.857 L10 []#173003 current goal: before update: 08:19:43.857 L10 []#173004 we are planning to push new seqnum=#1 08:19:43.857 L10 []#173005 current goal: after update: , sh0 to [3cqfcfch], sh1 to [ysse5rzw], sh2 to [vl3r33qr], sh3 to [xazwtxob], sh4 to [t6b4wzcs], sh5 to [6i2sk6xm], sh6 to [wbaqeiex], sh7 to [qlnepnf6], sh8 to [svq7zfma], sh9 to [55khl43t] 08:19:43.857 L10 []#173006 we are planning to push new seqnum=#1 08:19:43.859 L20 []#173007 Starting push 08:19:44.306 L20 []#173008 storage: slot_writev iarlyicewprjrxlabf5pvsgaiu 08:19:44.320 L20 []#173009 _got_write_answer from 3cqfcfch, share 0 08:19:44.320 L20 []#173010 found the following surprise shares: set([]) 08:19:44.321 L20 []#173011 wrote successfully: adding new share to servermap 08:19:44.864 L20 []#173012 _got_write_answer from qlnepnf6, share 7 08:19:44.864 L20 []#173013 found the following surprise shares: set([]) 08:19:44.864 L20 []#173014 wrote successfully: adding new share to servermap 08:19:45.097 L20 []#173015 _got_write_answer from svq7zfma, share 8 08:19:45.097 L20 []#173016 found the following surprise shares: set([7]) 08:19:45.098 L30 []#173017 they had shares [7] that we didn't know about 08:19:46.178 L20 []#173018 wrote successfully: adding new share to servermap 08:19:46.194 L20 []#173019 _got_write_answer from 6i2sk6xm, share 5 08:19:46.194 L20 []#173020 found the following surprise shares: set([]) 08:19:46.194 L20 []#173021 wrote successfully: adding new share to servermap 08:19:46.208 L20 []#173022 _got_write_answer from 55khl43t, share 9 08:19:46.208 L20 []#173023 found the following surprise shares: set([]) 08:19:46.208 L20 []#173024 wrote successfully: adding new share to servermap 08:19:46.877 L20 []#173025 _got_write_answer from ysse5rzw, share 1 08:19:46.878 L20 []#173026 found the following surprise shares: set([]) 08:19:46.878 L20 []#173027 wrote successfully: adding new share to servermap 08:19:47.432 L20 []#173028 _got_write_answer from vl3r33qr, share 2 08:19:47.432 L20 []#173029 found the following surprise shares: set([1]) 08:19:47.432 L30 []#173030 they had shares [1] that we didn't know about 08:19:47.433 L20 []#173031 wrote successfully: adding new share to servermap 08:19:47.641 L20 []#173032 _got_write_answer from wbaqeiex, share 6 08:19:47.641 L20 []#173033 found the following surprise shares: set([5]) 08:19:47.641 L30 []#173034 they had shares [5] that we didn't know about 08:19:47.641 L20 []#173035 wrote successfully: adding new share to servermap 08:19:51.945 L20 []#173036 _got_write_answer from xazwtxob, share 3 08:19:51.945 L20 []#173037 found the following surprise shares: set([]) 08:19:51.945 L20 []#173038 wrote successfully: adding new share to servermap 08:19:55.978 L20 []#173039 _got_write_answer from t6b4wzcs, share 4 08:19:55.978 L20 []#173040 found the following surprise shares: set([3]) 08:19:55.978 L30 []#173041 they had shares [3] that we didn't know about 08:19:57.085 L20 []#173042 wrote successfully: adding new share to servermap 08:19:57.086 L20 []#173043 Publish failed with UncoordinatedWriteError 08:19:57.106 L20 []#173044 web: 127.0.0.1 POST /uri/[CENSORED]..?t=mkdir 500 95 ``` Creating MDMF files or directories in the WUI, and un-linking throws the following KeyError, but the job actually gets done. (I manually created the tahoe: alias that way.) ``` > tahoe rm tahoe:testfile ERROR: 500 Internal Server Error "Traceback (most recent call last): File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/base.py\", line 878, in runUntilCurrent call.func(*call.args, **call.kw) File \"/home/debian/.local/lib/python2.7/site-packages/foolscap/eventual.py\", line 26, in _turn cb(*args, **kwargs) File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 459, in callback self._startRunCallbacks(result) File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 567, in _startRunCallbacks self._runCallbacks() --- <exception caught here> --- File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 653, in _runCallbacks current.result = callback(current.result, *args, **kw) File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 856, in _retry f.trap(UncoordinatedWriteError) File \"/home/debian/.local/lib/python2.7/site-packages/twisted/python/failure.py\", line 346, in trap self.raiseException() File \"/home/debian/.local/lib/python2.7/site-packages/twisted/internet/defer.py\", line 653, in _runCallbacks current.result = callback(current.result, *args, **kw) File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 854, in <lambda> self._modify_once(modifier, first_time)) File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 880, in _modify_once d = self._try_to_download_data() File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 958, in _try_to_download_data d = self._read(c, fetch_privkey=True) File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/filenode.py\", line 980, in _read d = r.download(consumer, offset, size) File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 253, in download self._start_download(consumer, offset, size) File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 265, in _start_download self._setup_download() File \"/home/debian/.local/lib/python2.7/site-packages/allmydata/mutable/retrieve.py\", line 301, in _setup_download shares = versionmap[self.verinfo] exceptions.KeyError: (12, \"\\x9f\\x02FDS5O\\xed\\x1fEz\\xa2\\x02\\xd1\\x97\\xb9%\\x0b\\xef\\xc2{\\xa6\\xcc\\x0b'&\\xf3]\\x9c\\x8e\\x05\\xa7\", None, 131073, 1108, 3, 10, \"\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x0c\\x9f\\x02FDS5O\\xed\\x1fEz\\xa2\\x02\\xd1\\x97\\xb9%\\x0b\\xef\\xc2{\\xa6\\xcc\\x0b'&\\xf3]\\x9c\\x8e\\x05\\xa7\\x03\\n\\x00\\x00\\x00\\x00\\x00\\x02\\x00\\x01\\x00\\x00\\x00\\x00\\x00\\x00\\x04T\", (('EOF', 2585), ('verification_key', 1731), ('enc_privkey', 123), ('share_data', 2167), ('signature', 1475), ('block_hash_tree', 2553), ('share_hash_chain', 1339), ('verification_key_end', 2023))) ``` I had no issues on the testGrid.

tahoe-lafs added the

labels 2017-06-03 09:32:12 +00:00

tahoe-lafs added this to the undecided milestone 2017-06-03 09:32:12 +00:00

nwks commented

2017-06-03 09:33:41 +00:00

Author

Owner

Attachment incident-2017-06-03--07-14-11Z-kdajupi.flog.bz2 (69031 bytes) added

UncoordinatedWriteError happening 1

**Attachment** incident-2017-06-03--07-14-11Z-kdajupi.flog.bz2 (69031 bytes) added [UncoordinatedWriteError](wiki/UncoordinatedWriteError) happening 1

incident-2017-06-03--07-14-11Z-kdajupi.flog.bz2

67 KiB

nwks commented

2017-06-03 09:34:04 +00:00

Author

Owner

Attachment incident-2017-06-03--07-14-34Z-jfukavy.flog.bz2 (69086 bytes) added

UncoordinatedWriteError happening 2

**Attachment** incident-2017-06-03--07-14-34Z-jfukavy.flog.bz2 (69086 bytes) added [UncoordinatedWriteError](wiki/UncoordinatedWriteError) happening 2

incident-2017-06-03--07-14-34Z-jfukavy.flog.bz2

68 KiB

nwks commented

2017-06-03 09:34:18 +00:00

Author

Owner

Attachment incident-2017-06-03--08-55-19Z-w3josey.flog.bz2 (69940 bytes) added

UncoordinatedWriteError happening 3

**Attachment** incident-2017-06-03--08-55-19Z-w3josey.flog.bz2 (69940 bytes) added [UncoordinatedWriteError](wiki/UncoordinatedWriteError) happening 3

incident-2017-06-03--08-55-19Z-w3josey.flog.bz2

68 KiB

nwks commented

2017-06-21 16:20:42 +00:00

Author

Owner

I've attached a new full flog containing the whole node startup sequence, as well as the UncoordinatedWriteError resulting from the publish starting at event !#7738.

After some additional logging I found that I end up with duplicated servers (i.e. multiples storage server clients pointing to the same destination). And so two share writers end up writing to the same destination, and find that this destination holds other shares beside their own. I've attached a new full flog containing the whole node startup sequence, as well as the UncoordinatedWriteError resulting from the publish starting at event !#7738.

nwks commented

2017-06-21 16:23:51 +00:00

Author

Owner

Attachment full_2017_06_21.zip (358626 bytes) added

Node startup sequence and UncoordinatedWriteError at !#7738

**Attachment** full_2017_06_21.zip (358626 bytes) added Node startup sequence and UncoordinatedWriteError at !#7738

full_2017_06_21.zip

350 KiB

nwks commented

2017-06-23 16:58:21 +00:00

Author

Owner

Investigated further and found the issue: some servers are misconfigured and share the same FURL.

As NativeStorageServer.get_serverid() returns key_s, it is possible for StorageFarmBroker to register multiples (misconfigured) servers with the same FURL, triggering the behavior described in my previous comment.

In release 1.11, _tubid was used in get_serverid() instead of key_s, so this issue did not exist.
Also it is not yet widespread on the I2P grid as most nodes are still running 1.10.

Workaround: restore the return value of NativeStorageServer.get_serverid() to _tubid, instead of key_s.

Investigated further and found the issue: some servers are misconfigured and share the same FURL. As *NativeStorageServer.get_serverid()* returns key_s, it is possible for *StorageFarmBroker* to register multiples (misconfigured) servers with the same FURL, triggering the behavior described in my previous comment. In release 1.11, *_tubid* was used in *get_serverid()* instead of *key_s*, so this issue did not exist. Also it is not yet widespread on the I2P grid as most nodes are still running 1.10. Workaround: restore the return value of *NativeStorageServer.get_serverid()* to *_tubid*, instead of *key_s*.

tahoe-lafs changed title from ~~UncoordinatedWriteError on SDMF directory creation (I2P grid)~~ to Multiples storage servers can be registered with the same FURL (UncoordinatedWriteError on I2P grid)

2017-06-23 17:20:25 +00:00

tahoe-lafs added

c/code-network

and removed

c/unknown

labels 2017-06-24 09:03:04 +00:00

warner commented

2017-07-04 19:08:37 +00:00

Thanks for the detailed investigation!

Storage servers in Tahoe are primarily identified by their !Ed25519 public verifying key, and the FURL is supposed to be an attribute of the storage server (rather than an identifier). The idea going forward is that some storage servers won't even speak Foolscap, so they won't have FURLs (they'll probably have http:// URLs instead).

It wasn't always that way. In the beginning, we were so focused on Foolscap that we used the "tubid" portion of the Foolscap FURL at a node identifier (and we were so focused on P2P that we frequently called it a "peerid"). But when we started thinking about non-Foolscap nodes, we realized that was a mistake.

In 1.12 we finally switched from using the FURL-derived tubid to using the new !Ed25519 pubkey. Servers have signed their Introducer announcements using the corresponding private signing key since the 1.10 release. Clients build local objects (instances of allmydata.storage_client.NativeStorageServer) to represent them, and those NativeStorageServer objects are indexed by a "serverid".

I did a big pass to hand these server objects around instead of string-ish identifiers, and then to consistently use the word "serverid" in the code when we did need to talk about the server objects. And then we made a second change to build this from the !ed25519 key instead of the tubid, except in a backwards-compatible case where the (older) server wasn't publishing an !ed25519 key. In 1.12, we removed support for these old unsigned announcements, so all the client-side server objects ought to have a pubkey-based serverid now, and this backwards-compatibility code was removed.

So, misconfigured servers that announce the wrong FURL are a problem, but it should be only the server's problem (clients won't be able to connect to that server: it'd be like you giving me the wrong email address and then me wondering why my emails weren't getting through, or going to the wrong person). But if the client is getting confused by that, that's something we need to fix.

So the client thinks it is talking to two distinct servers, but they both happen to be connecting to the same one. So like you said, then client will send two shares to the same server, and they'll also see both shares as appearing at both servers.

One of those shares is wrong: the lease renew/cancel secrets will be computed for the wrong server, and the "write enabler" secret (which authorizes mutations of mutable shares) will be wrong. So when the client attempts to modify both of the shares that it sees, it will get an exception for one of them (or the request will be ignored: it's a critical distinction, but I forget how the code currently behaves).

But most critically, as you discovered, writing to share 1 on "server A" will cause share 1 on "server B" to spontaneously change, which looks exactly like an UncoordinatedWriteError.

The shallow solution might be to have the client watch for duplicate FURLs, and complain, or reject the second one as a duplicate. That's not very satisfying though, because a server that wants to cause problems could duplicate the FURL of any other known server, and then if it got lucky and was processed first, it could prevent you from reaching their victim server. The malicious server can't pretend to be someone else (because of the keys), but it can (sometimes) prevent you from talking to someone else, which isn't great.

The deeper solution, which I guess I should have thought about when I first implemented the !ed25519 key scheme, is that the server needs to prove its control over that key when the client connects to it, instead of merely when it publishes the announcement. Or, at least the server needs a way to let the client know which server they just connected to, and the client should check this before sending any shares.

I need to think about this more.. getting a strong two-way binding between serverid (the !ed25519 pubkey) and the FURL sounds tricky, but also I don't think we strictly need it. My immediate thought was to have the server (at the announced FURL) return a signed JSON blob which contains the actual FURL to use. But I don't think that solves the problem at all.

A not-so-strong binding might be sufficient: put the server's !ed25519 serverid in the VERSION blob that it hands out to all clients that connect to the FURL. The client would check this value against the serverid they were intending to connect to. So we know that the !ed25519 signing-key holder wanted to use this FURL, and we know that this FURL wants to be known by the matching verifying key.

Actually, that second approach does sound like a strong bidirectional binding. The VERSION blob is controlled by the FURL-owner (the rogue server has no way to control the object pointed to by the victim server's FURL, it can merely send the client to somebody else's object), and Foolscap provides a transport channel bound to the FURL, so nobody else can see or modify that blob.

Ok, so the task is then:

update the VERSION blob to return the !ed25519 serverid (remote_get_version, in src/allmydata/storage/server.py), probably in a key named serverid
update NativeStorageServer._got_versioned_service in src/allmydata/storage_client.py to compare rref.version["serverid"] against self._server_id, and if they don't match, then.. fail somehow

What about backwards compatibility? Most servers won't be publishing this serverid VERSION key yet. We want a way for grids that are having this problem to be able to fix it, but without causing a flag day for everyone. We could say that the client only checks for equality if the server actually publishes its own serverid. Then once the victim server (the one whose FURL is being copied by someone else) and the victim clients have upgraded, the new clients should fail to establish a working connection to the bogus server.

The other interesting question is how it should fail. We could drop the TCP connection outright, but the client will treat that as a network error and begin to reconnect right away. We probably need to prevent reconnections until we get a new announcement (hopefully with a better FURL, although realistically that may never happen). Mainly we need to make sure the StorageFarmBroker never returns this incomplete/unusable NativeStorageServer object to the uploader/downloader code, which means not setting self._is_connected = True in _got_versioned_service.

So maybe it'd be enough to let the connection remain up, but leave _is_connected at False, so the broker won't actually use it for anything. That wouldn't cause any reconnections to happen. It'd be a waste of a file descriptor, but probably easier than any other fix. With more effort, we could change NativeStorageServer to have an additional state (beyond "connected", "connecting", "waiting"), something like "no longer interested", which shuts down the Reconnector. We could also set the connection status to "serverid did not match", to tell the user what went wrong.

Open question: is there anything we can do to mitigate this without a server upgrade? The client can look for duplicate FURLs (the "shallow" fix), which will tell us that something is going wrong, but I don't think we have enough information to know which connection is the right one, so the best we could do is display a warning message somewhere.

We could have the server look for duplicate FURLs, but again the best it can do is display a warning somewhere.

We could have each server subscribe to hear about other servers (they currently do anyways, but only because we haven't yet built a "server-only" node, which we totally want to do). Then if server A sees someone else announce its own FURL, it could complain somehow. But if we're changing server code to do that, then we could jump ahead to having the server publish its own serverid.

Thanks for the detailed investigation! Storage servers in Tahoe are primarily identified by their !Ed25519 public verifying key, and the FURL is supposed to be an attribute of the storage server (rather than an identifier). The idea going forward is that some storage servers won't even speak Foolscap, so they won't have FURLs (they'll probably have `http://` URLs instead). It wasn't always that way. In the beginning, we were so focused on Foolscap that we used the "tubid" portion of the Foolscap FURL at a node identifier (and we were so focused on P2P that we frequently called it a "peerid"). But when we started thinking about non-Foolscap nodes, we realized that was a mistake. In 1.12 we finally switched from using the FURL-derived tubid to using the new !Ed25519 pubkey. Servers have signed their Introducer announcements using the corresponding private signing key since the 1.10 release. Clients build local objects (instances of `allmydata.storage_client.NativeStorageServer`) to represent them, and those `NativeStorageServer` objects are indexed by a "serverid". I did a big pass to hand these server objects around instead of string-ish identifiers, and then to consistently use the word "serverid" in the code when we did need to talk about the server objects. And then we made a second change to build this from the !ed25519 key instead of the tubid, except in a backwards-compatible case where the (older) server wasn't publishing an !ed25519 key. In 1.12, we removed support for these old unsigned announcements, so all the client-side server objects ought to have a pubkey-based serverid now, and this backwards-compatibility code was removed. So, misconfigured servers that announce the wrong FURL are a problem, but it should be only the server's problem (clients won't be able to connect to that server: it'd be like you giving me the wrong email address and then me wondering why my emails weren't getting through, or going to the wrong person). But if the client is getting confused by that, that's something we need to fix. So the client thinks it is talking to two distinct servers, but they both happen to be connecting to the same one. So like you said, then client will send two shares to the same server, and they'll also see both shares as appearing at both servers. One of those shares is wrong: the lease renew/cancel secrets will be computed for the wrong server, and the "write enabler" secret (which authorizes mutations of mutable shares) will be wrong. So when the client attempts to modify both of the shares that it sees, it will get an exception for one of them (or the request will be ignored: it's a critical distinction, but I forget how the code currently behaves). But most critically, as you discovered, writing to share 1 on "server A" will cause share 1 on "server B" to spontaneously change, which looks exactly like an `UncoordinatedWriteError`. The shallow solution might be to have the client watch for duplicate FURLs, and complain, or reject the second one as a duplicate. That's not very satisfying though, because a server that wants to cause problems could duplicate the FURL of any other known server, and then if it got lucky and was processed first, it could prevent you from reaching their victim server. The malicious server can't pretend to be someone else (because of the keys), but it *can* (sometimes) prevent you from talking to someone else, which isn't great. The deeper solution, which I guess I should have thought about when I first implemented the !ed25519 key scheme, is that the server needs to prove its control over that key when the client connects to it, instead of merely when it publishes the announcement. Or, at least the server needs a way to let the client know which server they just connected to, and the client should check this before sending any shares. I need to think about this more.. getting a strong two-way binding between serverid (the !ed25519 pubkey) and the FURL sounds tricky, but also I don't think we strictly need it. My immediate thought was to have the server (at the announced FURL) return a signed JSON blob which contains the actual FURL to use. But I don't think that solves the problem at all. A not-so-strong binding might be sufficient: put the server's !ed25519 serverid in the VERSION blob that it hands out to all clients that connect to the FURL. The client would check this value against the serverid they were intending to connect to. So we know that the !ed25519 signing-key holder wanted to use this FURL, and we know that this FURL wants to be known by the matching verifying key. Actually, that second approach *does* sound like a strong bidirectional binding. The VERSION blob is controlled by the FURL-owner (the rogue server has no way to control the object pointed to by the victim server's FURL, it can merely send the client to somebody else's object), and Foolscap provides a transport channel bound to the FURL, so nobody else can see or modify that blob. Ok, so the task is then: * update the VERSION blob to return the !ed25519 serverid (`remote_get_version`, in src/allmydata/storage/server.py), probably in a key named `serverid` * update `NativeStorageServer._got_versioned_service` in src/allmydata/storage_client.py to compare `rref.version["serverid"]` against `self._server_id`, and if they don't match, then.. fail somehow What about backwards compatibility? Most servers won't be publishing this `serverid` VERSION key yet. We want a way for grids that are having this problem to be able to fix it, but without causing a flag day for everyone. We could say that the client only checks for equality if the server actually publishes its own serverid. Then once the victim server (the one whose FURL is being copied by someone else) and the victim clients have upgraded, the new clients should fail to establish a working connection to the bogus server. The other interesting question is how it should fail. We could drop the TCP connection outright, but the client will treat that as a network error and begin to reconnect right away. We probably need to prevent reconnections until we get a new announcement (hopefully with a better FURL, although realistically that may never happen). Mainly we need to make sure the `StorageFarmBroker` never returns this incomplete/unusable `NativeStorageServer` object to the uploader/downloader code, which means not setting `self._is_connected = True` in `_got_versioned_service`. So maybe it'd be enough to let the connection remain up, but leave `_is_connected` at False, so the broker won't actually use it for anything. That wouldn't cause any reconnections to happen. It'd be a waste of a file descriptor, but probably easier than any other fix. With more effort, we could change `NativeStorageServer` to have an additional state (beyond "connected", "connecting", "waiting"), something like "no longer interested", which shuts down the `Reconnector`. We could also set the connection status to "serverid did not match", to tell the user what went wrong. Open question: is there anything we can do to mitigate this *without* a server upgrade? The client can look for duplicate FURLs (the "shallow" fix), which will tell us that something is going wrong, but I don't think we have enough information to know which connection is the right one, so the best we could do is display a warning message somewhere. We could have the *server* look for duplicate FURLs, but again the best it can do is display a warning somewhere. We could have each server subscribe to hear about other servers (they currently do anyways, but only because we haven't yet built a "server-only" node, which we totally want to do). Then if server A sees someone else announce its own FURL, it could complain somehow. But if we're changing server code to do that, then we could jump ahead to having the server publish its own serverid.