gossip: unexpected "n%d has been removed from the cluster" errors

[petermattis]

A customer reports a test cluster getting wedged (no queries going through) during simulation of a multi-node outage. The scenario is a 15-node cluster, configured with 15-way replication (confirmed that every zone config has 15-way replication). During the test, a set of "ping" queries are being run against each node in the cluster. These queries are simple SELECT * FROM <table> LIMIT 1 for each of the customers tables (~10). 5 of the nodes are taken down and left down for 5 minutes so that the cluster reports them as dead. These 5 nodes are then brought back up. Fairly quickly, 2 of these restarted nodes start showing up in the logs of every node with the error in the title. For example, n7 has been removed from the cluster. Several minutes of waiting, and the "ping" queries suddenly stop returning. It appears to happen to one particular table.

It is unclear if the has been removed from the cluster errors are related to the wedge, but they are disconcerting as they absolutely shouldn't happen. The code which generates this error is Gossip.getNodeDescriptorLocked. The error is only returned if a node descriptor is present in the info store, but contains a zero node ID or an empty address. It is extremely curious that the node descriptor is not in the cached Gossip.nodeDescs map.

This problem was seen on 2.1.3 (to be precise, the problem was seen on a custom 2.1.X binary which happens to be the same SHA as what became 2.1.3). The cluster has a relatively modest amount of data (a little over 100 ranges).

[petermattis]

Perusing logs that the customer provided. On one node I see:

W190118 19:47:39.434514 284 server/status/recorder.go:388  [n1,summaries] n6 has been removed from the cluster

Looking at that time frame in the n6 logs I find:

I190118 19:47:31.747467 22 gossip/gossip.go:395  [n6] NodeDescriptor set to node_id:6 address:<network_field:"tcp" address_field:"cockroachdb-2.cockroachdb.default.svc.cluster.local:26257" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:1 patch:0 unstable:0 > build_tag:"v2.1.2-35-g0c87b11" started_at:1547840851742669721
...
I190118 19:47:37.317456 24 storage/stores.go:261  [n6] wrote 14 node addresses to persistent storage
I190118 19:47:37.317484 24 gossip/gossip.go:808  [n6] removed n6 from gossip

This is super suspicious. A node should never remove itself from gossip like that.

[petermattis]

I've reproduced the removed n* from gossip messages.

1. Start a 9-node cluster
2. Stop nodes 7-9
3. Re-arrange the data directories so that node 7 uses node 9's directory, node 8 uses node 7's, and node 9 uses node 8's
4. Restart nodes 7-9

Fairly quickly you'll see the removed n* from gossip messages in the logs. I also see this funkiness on the network latency page:

I'm not sure if that means that n9 can't talk to anyone, or nothing can talk to n9. Regardless, it isn't good and seems to persist for a long time. In fact, I bet it persists until the node gossips its node descriptor again which occurs on a 1h interval.

I believe the problem is coming from this code in gossip/gossip.go:

	// If the new node's address conflicts with another node's address, then it
	// must be the case that the new node has replaced the previous one. Remove
	// it from our set of tracked descriptors to ensure we don't attempt to
	// connect to its previous identity (as came up in issue #10266).
	oldNodeID, ok := g.bootstrapAddrs[desc.Address]
	if ok && oldNodeID != unknownNodeID && oldNodeID != desc.NodeID {
		log.Infof(ctx, "removing n%d which was at same address (%s) as new node %v",
			oldNodeID, desc.Address, desc)
		g.removeNodeDescriptorLocked(oldNodeID)

		// Deleting the local copy isn't enough to remove the node from the gossip
		// network. We also have to clear it out in the infoStore by overwriting
		// it with an empty descriptor, which can be represented as just an empty
		// byte array due to how protocol buffers are serialized.
		// Calling addInfoLocked here is somewhat recursive since
		// updateNodeAddress is typically called in response to the infoStore
		// being updated but won't lead to deadlock because it's called
		// asynchronously.
		key := MakeNodeIDKey(oldNodeID)
		var emptyProto []byte
		if err := g.addInfoLocked(key, emptyProto, NodeDescriptorTTL); err != nil {
			log.Errorf(ctx, "failed to empty node descriptor for n%d: %s", oldNodeID, err)
		}
	}

This code is fairly old, arriving 2 years ago in #10544.

[petermattis]

Something I forgot to mention in the original message, the customer is running on kubernetes. The log files in the debug zip provide evidence that hostnames are moving around the nodes in the cluster when the nodes are rebooted. For example, the hostname cockroachdb-2 has been used by n1, n3, n6, n8, and n9 at different times.

[petermattis]

Unsurprisingly, this is a problem on master too.

[petermattis]

I think this is effectively creating an asymmetric network partition. The gossiped node descriptors are used to locate the address for a node. If the node descriptor is deleted from gossip, other nodes in the system won't be able to talk to the node, though the node will be able to talk to them. This likely will cause all sorts of badness in the system.

[petermattis]

The node address conflict detection code exists for a good reason. See #10266. I might try reproducing that original problem and see if there is a different approach to remedy it.

Another option is more of a hack: whenever a node receives an info which deletes its node descriptor, it can re-gossip its node descriptor.

I need to think about this more.

Cc @bdarnell and @tbg to see if they have better thoughts.

[tbg]

I have to look at this in more detail, but the "deleting from Gossip" code has always bothered me. Why exactly was #10266 such a big problem? A node (say n1) gets wiped, another node (say n2) takes its address, so the cluster may try to connect to n2 when it wants n1. But n1 is gone, so how can cluster health depend on connections to it? The real problem (though I didn't see this mentioned as such in #10266) is that it can actually be dangerous to send stuff to n2 when it was meant for n1 (unintentionally byzantine?)

We never look up addresses by nodeID, it's always the other way around. So, in theory, I tend to think that leaving the old entry in Gossip should work fine, though I would add a NodeID check -- the connection that is supposedly connecting to nX should actually be confirmed as connecting to nX.

In this issue, the problem becomes that we're removing a nodeID that is actually still active (albeit under a different address), and we unconditionally nuke (overwrite) it, right? That should also be solved if we removed the nuking (which seems a little too unconditional -- it's not even attempting to check which descriptor it overrides; that desc wouldn't have the bootstrapAddr any more in this case, though fixing that will only "mostly" fix the issue).

I'm not sure if that means that n9 can't talk to anyone, or nothing can talk to n9

One day I'll polish #33299 and then you will know.

[petermattis]

I have to look at this in more detail, but the "deleting from Gossip" code has always bothered me. Why exactly was #10266 such a big problem? A node (say n1) gets wiped, another node (say n2) takes its address, so the cluster may try to connect to n2 when it wants n1. But n1 is gone, so how can cluster health depend on connections to it? The real problem (though I didn't see this mentioned as such in #10266) is that it can actually be dangerous to send stuff to n2 when it was meant for n1 (unintentionally byzantine?)

I don't know. I'm going to spend some time reproducing that scenario and see what badness emerges. It is possible that we've since fixed something else that was causing problems in this area. 2 years ago was pre-1.0.

[petermattis]

PS The scenario described above reproduces the "missing address" log message on #29035 on 2.1.3, but not on master. I'm pretty sure one of my changes to be more defensive about never returning empty addresses is responsible. I'll track down which one and backport to 2.1.

[petermattis]

We never look up addresses by nodeID, it's always the other way around. So, in theory, I tend to think that leaving the old entry in Gossip should work fine, though I would add a NodeID check -- the connection that is supposedly connecting to nX should actually be confirmed as connecting to nX.

Eh? We lookup the address by nodeID all the time. See Gossip.GetNodeIDAddress and the usage of Gossip as an AddressResolver. Am I completely misunderstanding what you are saying?

[tbg]

No, I just wrote the opposite of what I was trying to say. We always look up NodeID -> Address. Sorry about the confusion. Does the rest check out? If a node is gone, nobody should care about what we store under its NodeID, though any goroutines now knowing that node X is dead shouldn't accidentally talk to node Y thinking they've got node X.

[knz]

I was able to repro this with 4 nodes. Here's a script that repros the problem all the time in under 2minutes:

#! /bin/sh

C=$PWD/cockroach
d=$PWD/repro-34120

killall -9 cockroach cockroachshort

rm -rf "$d"
mkdir -p "$d"
cd "$d"

# Start cluster
for n in 1 2 3 4; do
    (
        mkdir -p d$n
        cd d$n
        $C start --background --listen-addr=localhost:2600$n --http-addr=localhost:2700$n --insecure --join=localhost:26001
    )
done
# Init cluster
$C init --host localhost:26001 --insecure

# Create some ranges
(
    for i in `seq 1 10`; do
        echo "create table t$i(x int); insert into t$i(x) values(1);"
    done
) | $C sql --insecure --host localhost:26001

# Wait for cluster to stabilize
tail -f d1/cockroach-data/logs/cockroach.log &
tailpid=$!
while true; do
    sleep 2
    lastlines=$(tail -n 2 d1/cockroach-data/logs/cockroach.log | grep 'runtime stats' | wc -l)
    if test $lastlines -lt 2; then
        continue
    fi
    break
done
kill -9 $tailpid
echo "OK"

# Stop the last two nodes.
$C quit --host localhost:26003 --insecure
$C quit --host localhost:26004 --insecure

# Restart with node shift
(
    cd d3
    $C start --background --listen-addr=localhost:26004 --http-addr=localhost:27004 --insecure
)

# Start a load on all tables
(
    while true; do
        sleep 1
        for i in `seq 1 10`; do
            echo "select * from t$i limit 1"
        done
    done
) | $C sql --insecure --host localhost:26001 &>sql.log &

exec tail -f d1/cockroach-data/logs/cockroach.log