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

[nwks]

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.

[nwks]

UncoordinatedWriteError? happening 1

[nwks]

UncoordinatedWriteError? happening 2

[nwks]

UncoordinatedWriteError? happening 3

[nwks]

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]

Node startup sequence and UncoordinatedWriteError at #7738

[nwks]

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.

[warner]

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.