Topology tests: node bootstrap sometimes fails due to Operation timed out for system_distributed_everywhere.cdc_generation_descriptions_v2

[kbr-scylla]

This happens rarely in CI builds / next promotions and is very hard to reproduce, but I think I found the cause.

When a node is booting, it tries to write some data to system_distributed_everywhere.cdc_generation_descriptions_v2. The write is sent to all existing nodes and uses CL=ALL.

Sometimes in topology tests when we create a cluster, when we boot the second node in the cluster, the write sent by the second node to the first node is lost: the mutation RPC call never arrives at the first node. Because it's a one-way RPC, storage_proxy is not "aware" of this and waits asynchronously for the response, then times out after 60s (which is the hardcoded timeout for this write).

After some investigation, I'm pretty sure that this is caused by the second node dropping connections to the first node in this code:

future<> storage_service::notify_joined(inet_address endpoint) {
...
    co_await container().invoke_on_all([endpoint] (auto&& ss) {
        ss._messaging.local().remove_rpc_client_with_ignored_topology(netw::msg_addr{endpoint, 0});
        return ss._lifecycle_notifier.notify_joined(endpoint);
    });
...
}

I think this is the cause because after putting a log message there, I observed in the failed runs that the message is printed in the same millisecond that the mutation write RPC is sent.

This notify_joined function is called when a node observes that another node is in NORMAL state. In this case, the joining node observes that the first node is indeed NORMAL, gossiper calls storage_service::handle_state_normal which performs some operations and then calls storage_service::notify_joined. This races with the bootstrap procedure, and sometimes happens exactly at the moment of writing the CDC data, causing the write to be lost.

This doesn't happen in production clusters where a lot of sleeps are included in the boot procedure, so by the time we make the CDC write, handle_state_normal had been called and finished a "long time ago". The problem is test specific, where we set skip_wait_for_gossip_to_settle and ring_delay: 0.

I'd say that this is another example of the larger umbrella issue: #12015.

[kbr-scylla]

This patch looks like it should have fixed the problem, at least from the description:
5363616

But it seems that the wait_for_normal_state_handled_on_boot call happens too late - in run_bootstrap_ops, which is called after the CDC write is done.

Perhaps we should move it earlier, before this line:

            cdc_gen_id = cdc_gen_service.make_new_generation(bootstrap_tokens, !is_first_node()).get0();

cc @asias

[kostja]

I don't think it's test specific. The tests show that a lot of bootstrap code is not prepared for RPC errors. The bootstrap simply fails in this case, moreover, the reason is hard to nail down. An external user will never figure out from the logs that this is a flaky failure - and won't know how to recover from it.
Bootstrap code should tolerate RPC errors. This includes both gossiper and internal writes to schema_distributed tables. Writing it off a testing issue won't cut it.

Besides, going forward, for topology testing, we will have a lot of concurrent node operations going on. How are you planning to make these tests reliable unless the problem is fixed in scylla code, not in the testing code?

[kostja]

@avikivity please provide your input

[kbr-scylla]

An external user will never figure out from the logs that this is a flaky failure - and won't know how to recover from it.

Note that this will not happen in production because of ring_delay / wait_for_gossip_to_settle sleeps.