coredump at replica::update_local_configuration()

[qinzuoyan]

found by kill_test.

last log:

D18:57:51.211 (1469905071211742378 8248) replica5.replica0.0800823c00010009: replica.stub:714:on_add_learner(): 1.8@10.108.187.19:34805: received add learner, primary = 10.108.187.19:34803, ballot = 2537, status = replication::partition_status::PS_POTENTIAL_SECONDARY, last_committed_decree = 3062357
D18:57:51.211 (1469905071211783001 8248) replica5.replica0.0800823c00010009: replica.learn:997:on_add_learner(): 1.8@10.108.187.19:34805: process add learner, primary = 10.108.187.19:34803, ballot = 2537, status = replication::partition_status::PS_POTENTIAL_SECONDARY, last_committed_decree = 3062357
F18:57:51.211 (1469905071211802025 8248) replica5.replica0.0800823c00010009: /home/work/pegasus/rDSN/src/dist/replication/lib/replica_config.cpp:654:update_local_configuration(): assertion expression: false
F18:57:51.211 (1469905071211818785 8248) replica5.replica0.0800823c00010009: /home/work/pegasus/rDSN/src/dist/replication/lib/replica_config.cpp:654:update_local_configuration(): invalid execution path

coredump stack:

(gdb) bt
#0  0x00007fc050b605c9 in raise () from /lib64/libc.so.6
#1  0x00007fc050b61cd8 in abort () from /lib64/libc.so.6
#2  0x00007fc051e721e3 in dsn_coredump () at /home/work/pegasus/rDSN/src/core/core/service_api_c.cpp:307
#3  0x00007fc04feaf8f6 in dsn::replication::replica::update_local_configuration (this=0x7fbf7c000d60, config=..., same_ballot=true)
    at /home/work/pegasus/rDSN/src/dist/replication/lib/replica_config.cpp:654
#4  0x00007fc04fee10e2 in dsn::replication::replica::on_add_learner (this=0x7fbf7c000d60, request=...) at /home/work/pegasus/rDSN/src/dist/replication/lib/replica_learn.cpp:1008
#5  0x00007fc04ff11578 in dsn::replication::replica_stub::on_add_learner (this=0x285a160, request=...) at /home/work/pegasus/rDSN/src/dist/replication/lib/replica_stub.cpp:719
#6  0x00007fc04ff22ec6 in bool dsn::serverlet<dsn::replication::replica_stub>::register_rpc_handler<dsn::replication::group_check_request>(int, char const*, void (dsn::replication::replica_stub::*)(dsn::replication::group_check_request const&), dsn_global_partition_id)::{lambda(void*, void*)#1}::operator()(void*, void*) const (__closure=0x0, request=0x7fbfac001754, param=0x7fbf8c345560)
    at /home/work/pegasus/rDSN/include/dsn/cpp/serverlet.h:154
#7  0x00007fc04ff22f25 in bool dsn::serverlet<dsn::replication::replica_stub>::register_rpc_handler<dsn::replication::group_check_request>(int, char const*, void (dsn::replication::replica_stub::*)(dsn::replication::group_check_request const&), dsn_global_partition_id)::{lambda(void*, void*)#1}::_FUN(void*, void*) (request=0x7fbfac001754, param=0x7fbf8c345560)
    at /home/work/pegasus/rDSN/include/dsn/cpp/serverlet.h:148
#8  0x00007fc051e0581b in dsn::rpc_handler_info::run (this=0x7fbf8c350ed0, req=0x7fbfac001754) at /home/work/pegasus/rDSN/include/dsn/tool-api/task.h:272
#9  0x00007fc051e058d8 in dsn::rpc_request_task::exec (this=0x7fbfac001818) at /home/work/pegasus/rDSN/include/dsn/tool-api/task.h:304
#10 0x00007fc051e027b3 in dsn::task::exec_internal (this=0x7fbfac001818) at /home/work/pegasus/rDSN/src/core/core/task.cpp:204
#11 0x00007fc051e6ed4b in dsn::task_worker::loop (this=0x27f3e00) at /home/work/pegasus/rDSN/src/core/core/task_worker.cpp:357
#12 0x00007fc051e6ec9b in dsn::task_worker::run_internal (this=0x27f3e00) at /home/work/pegasus/rDSN/src/core/core/task_worker.cpp:334
#13 0x00007fc051e715dd in std::_Mem_fn<void (dsn::task_worker::*)()>::operator()<, void>(dsn::task_worker*) const (this=0x2847c30, __object=0x27f3e00) at /usr/include/c++/4.8.2/functional:601
#14 0x00007fc051e7153c in std::_Bind<std::_Mem_fn<void (dsn::task_worker::*)()> (dsn::task_worker*)>::__call<void, , 0ul>(std::tuple<>&&, std::_Index_tuple<0ul>) (this=0x2847c30, 
    __args=<unknown type in /home/work/pegasus/rDSN/install/lib/libdsn.core.so, CU 0x19d1c6c, DIE 0x1a431c8>) at /usr/include/c++/4.8.2/functional:1296
#15 0x00007fc051e714a8 in std::_Bind<std::_Mem_fn<void (dsn::task_worker::*)()> (dsn::task_worker*)>::operator()<, void>() (this=0x2847c30) at /usr/include/c++/4.8.2/functional:1355
#16 0x00007fc051e7143a in std::_Bind_simple<std::_Bind<std::_Mem_fn<void (dsn::task_worker::*)()> (dsn::task_worker*)> ()>::_M_invoke<>(std::_Index_tuple<>) (this=0x2847c30)
    at /usr/include/c++/4.8.2/functional:1732
#17 0x00007fc051e71387 in std::_Bind_simple<std::_Bind<std::_Mem_fn<void (dsn::task_worker::*)()> (dsn::task_worker*)> ()>::operator()() (this=0x2847c30) at /usr/include/c++/4.8.2/functional:1720
#18 0x00007fc051e71320 in std::thread::_Impl<std::_Bind_simple<std::_Bind<std::_Mem_fn<void (dsn::task_worker::*)()> (dsn::task_worker*)> ()> >::_M_run() (this=0x2847c18)
    at /usr/include/c++/4.8.2/thread:115
#19 0x00007fc0514b8da0 in ?? () from /lib64/libstdc++.so.6
#20 0x00007fc05254fdf3 in start_thread () from /lib64/libpthread.so.0
#21 0x00007fc050c211ad in clone () from /lib64/libc.so.6

[imzhenyu]

Nice. Will look into this later. A first guess is about primary to potential secondary?

[shengofsun]

@imzhenyu @qinzuoyan Why the bug happens is as follows:

1. A replica R crashed
2. Meta server detects R's crash, and starts to remove primaries from R. Firstly, meta updates the config to remote storage, while keep the local storage the old one. 3, The R comes back to alive, then starts to sync the config from meta. Meta returns the old config to it. So R still regards itself primary.
3. After meta updates the remote's config, it updates it locally. Then another replica serve S is reassigned as new primary.
4. Then meta orders S to add a new potential secondary for R.

So what about make primary -> potential_sec a valid switch if with larger ballot? Or simply just ignore all quey_config RPCs in meta when a config is syncing with remote?

[imzhenyu]

This is a violation of the perfect FD. Make switch valid breaks still. Ignore query-config amplifies the failure. A better way maybe:

• ensure the crashed replica does not restart within the period of the lease.
• make sure that update of the state on meta server is quick enough to dis-allow mis-syncing for the later restarted replicas, by updating the in memory state on meta server directly before syncing with the remote store? Any downsides?

[shengofsun]

• "Ensure the crashed replica doesn't restart within the period of lease" is not good. If a crashed replica server can recover asap, we may avoid switching of config status to give higher performance.
• No matter how quick you update the meta server's state, mis-syncing can't be prevented because the replica-server's disconnection event and the meta server's state is protected by different lock.
• Updating the memory meta state before syncing to remote is also not perfect. Because meta itself may crash too. This may lead to the meta server's state and replica server's state are inconsistent, which easily make the whole system in a mess. For instance: (1) A replica group: (Primary: invalid, secondary: [A, B], ballot: 10) (2) meta assigned A as primary: (Primary: A, secondary: B, ballot: 11). But this state hasn't sync to remote yet. (3) meta crashed (4) A new meta comes, with the replica group (Primary: invalid: secondary: [A, B], ballot: 10) (5) New meta assigned B as Primary.

[imzhenyu]

• correctness clearly has higher priority than performance, so if there is easy way out, let's get it. Not to mention that the replicas should not fail often when they get stable.
• have not looked into the details for long. My memory is that the FD's disconnect callback is invoked inside the FD lock to ensure consistency.
• you are right, it is not a good idea to update before syncing.

[shengofsun]

• For question 1: We can't control when the replica server will come back either. For the crash thing, we may force our program to sleep for a period before it starts to do the initialization. But what if the disconnection is due to the network partition?
• For question 2: (1) FD's disconnect callback is protected with FD lock, and invoked in FD's thread_pool. Before it starts to do modifiction on the meta state, it have to acquire a write lock(meta state lock). (2) query-config is called in meta_server's thread pool, and will have to acquire the same meta state lock before querying. (3) So what if the query-config get the read lock first?
• For question 2: Well, above is the old meta's logic before I do the refactoring. In the refactored version, the logic is different, and it is also impossible to do this.
• Besides, ignore the querying-config is not so bad. Coz we can only ignore the querying from replica servers which is dead in meta server.

[shengofsun]

In addition, making the "ps_primary->ps_potential_secondary" do violate the perfect FD, but I think for our PacificA is safe. The old primary can't commit any new mutations, and can only serve read for committed mutations.

[shengofsun]

@qinzuoyan @imzhenyu I'm trying to fix this with ignoring a config sync when a partition is syncing with remote storage. You may want to review

[imzhenyu]

@shengofsun How about we only ignore the reply for that specific partition? I'm worried about the failure amplification issue for the other replicas - a common pattern we see that may lead to cascading failures in the end.

[shengofsun]

Currently my fix is to add a new RPC for replica to do the config-sync, instead of the old query-configuration-by-node. So I don't see this a big deal. For clients who wants to query the cluster information from meta, there will be a response immediately, regardless of whether it is stale. For replica servers, only the "config-sync" is impacted. And on the other hand, we shouldn't response partial information for a "config-sync", as replica server will remove replicas if they are not found on meta server. In case of your worry, I can optimize this by checking whether a syncing partition is related to a node. Say, we may response a "config-sync" when the partition is adding a new node or removing other node:)

[imzhenyu]

I mean skipping the reply unnecessarily make the time of unavailability of other replicas longer, which may cause unnecessary fail-over. In certain cases, it can lead to cascading failures that take down many replicas offline. A better remedy could be let's mark specifically for that particular replica being under syncing, or we pre-calculate the result for that replica, and send calculated results to the sync clients.

[qinzuoyan]

用中文说下我的理解吧。

这里出core的原因：

• replica-server挂了后，很快被重新拉起，初始化完成后，启动FD去连master（参见replica_stub::initialize），meta-server收到心跳后，会更新心跳状态（参见failure_dector::on_ping_internal）
• 另一方面，meta-server在replica-server挂了后，经过一段时间后会感知到节点丢失，感知时间取决于FD的grace_period时间，此处为15秒（参见定期检测函数为failure_detector::check_all_records）
• failure_dector::on_ping_internal() 和 failure_detector::check_all_records() 对心跳状态的更新都要对failure_detector::_lock 加锁，因此总是串行执行的，而假设replica-server重发心跳的时间恰好在15秒左右，就有两种情况：
  • on_ping_internal() 在 check_all_records() 之前调用，那么心跳会被及时续上，meta-server根本不会感知replica-server的重启——这种情况无需进一步讨论
  • check_all_records() 在 on_ping_internal() 之前调用，心跳会先超时，进一步调用meta_server_failure_detector::on_worker_disconnected()，开始修改config将该primary踢掉，但是需要先更新zk，再更新内存状态。整个检测更新操作（从检测到心跳超时，到config完成更新）没法做到原子性，这就是问题所在

根据上面后一种情况继续，on_ping_internal() 在 check_all_records() 之后执行，重新建立心跳连接。replica-server在心跳建立后，会立即发起config_sync请求。meta-server在收到config_sync请求后，调用meta_service::on_query_configuration_by_node()获取configuration。如果该操作在“心跳超时触发的config更新”操作完成之前进行，就会获取到旧的状态，认为自己还是primary，引发后续的coredump。

我们在测试服务器上跑kill_test的时候，这个问题很难复现；而在单机跑kill_test的时候，这个问题较易复现。原因我认为是：单机的RPC太快了，造成重新建立心跳和发送config_sync的过程太快，增加了“query_config操作”在“心跳超时触发的config更新”操作完成之前执行的概率。

修复思路是：

• 让检测更新操作和查询操作不可能交错执行
• 所以我认为关键的改动在于：
  • 增加专门的meta_service::on_config_sync()函数，将真正的执行体server_state::on_config_sync()分派到THREAD_POOL_META_STATE上执行
  • 同时在server_state::on_config_sync()中检查是否正在更新config，如果是则忽略该config_sync请求
• 如何证明这样就不会交错执行？
  • 还是回到之前的假设，check_all_records() 在 on_ping_internal() 之前调用（通过failure_detector::_lock保证），即 check_all_records() 必定在 meta_service::on_config_sync() 之前调用，即meta_service::set_node_state() 必定在 meta_service::on_config_sync() 调用
  • set_node_state() 会将 server_state::on_change_node_state() enqueue到THREAD_POOL_META_STATE，而 on_config_sync() 会将 server_state::on_config_sync() enqueue到 THREAD_POOL_META_STATE，且优先级都是HIGH，根据thread_pool的task先进先出原则，server_state::on_change_node_state() 必定在 server_state::on_config_sync() 之前调用
  • server_state::on_change_node_state()会先更新zk，并将partition的stage设为pending_remote_sync状态；后面 server_state::on_config_sync() 在查询时也会先检查stage，如果发现有pending_remote_sync，则忽略该请求。

然后讨论meta-server如果忽略config_sync()请求，会有什么后果：

• 如果replica-server启动时的config_sync被忽略，触发超时，此时_state==NS_Connecting，会立即触发新的config_sync（参见replica_stub::on_node_query_reply）
• 如果replica-server定期config_sync任务被忽略，触发超时，则此次config_sync会被忽略，等待下一次config_sync

[qinzuoyan]

"I mean skipping the reply unnecessarily make the time of unavailability of other replicas longer, which may cause unnecessary fail-over."

@imzhenyu , I don't think it's a big problem. For initialing replica-server, if config_sync is ignored, then another config_sync will be started soon; for normal replica-server, ignoring config_sync would not affect availability.

Or, we can make meta-server return some error code like ERR_BUSY to replica-server, but not depending on timeout.

[qinzuoyan]

@imzhenyu ，我们对 @shengofsun 修改后的代码运行kill_test，已经一个晚上没有复现core了，要不我们先把改动merge了，然后将issue保留着，后面看还是否能更完美地解决？

[imzhenyu]

@qinzuoyan Thanks. ERR_BUSY will be much better instead of simply ignoring the replica request. The replica should try again very soon (e.g., after several hundreds of ms) to reduce the chance of unnecessary fail-over of the other replicas.

[imzhenyu]

@qinzuoyan @shengofsun 已经merge。这里主要有两点后面可以继续讨论：

• 这种可能会促发新的fail-over （sync timeout导致meta server上的LB踢出更多人，或者sync下去导致其他fail-over操作）的操作得多想一下会不会导致级联反应，参加我之前的一个 survey paper。其中一个问题就是错误放大failure的范围。当然并不是说这里的这个问题一定会导致cascading failure，但是要小心考虑。
• 第二是有没有可能pre-calculate zk那边写完后的结果，只要：（1）.zk 的写是串行的，(2). zk的写失败不会导致坏的结果

[shengofsun]

@imzhenyu @qinzuoyan

• 关于zk串行写：指的是对zk先发出的写请求一定先在zk端apply并且回调一定先执行吗？因为用的是异步接口，对不同的znode我们是不能保证这一点的。对于同一个znode，我们在meta server的代码逻辑里是强制串行写的，即对同一个znode同时只有一个写操作在进行。
• pre-calculate不好做的太复杂，一个可以的优化点是：对于正在更新的configuration，如果要修改的节点不是当前在做查询的节点，那么是可以把当前节点的状态返回给replica server端的。这一点的优化后面可以考虑加进来。
• 另外我们这个bug牵涉到了FD的机制，还有config sync时的rpc forward，要想完全修好不太容易……当前我觉得合理的解决思路是把failure_detector模块中的那个锁暴露出来，再加上现在对config_sync消息的选择性ignore才行。

[imzhenyu]

Close since it is done - can open later if we have better improvement later.