ra:process_command/2 times out if used immediately after a server restart

[mbj4668]

I have a problem where ra:process_command/2 times out. I have made a small example to reproduce the issue.

I start a single-node ra cluster, stop the single server, restart it, and call ra:process_command. Sometimes (1/10 - 1/20 on my machine) process_command times out. Checking the state shows that the single node is 'follower', rather than 'leader'. Calling trigger_election makes it snap out of this situation.

I run this script to trigger the problem:

#!/bin/sh

while true; do
    rm -rf ra_dir
    mkdir ra_dir
    erl -ra data_dir ra_dir -sname foo -s ra_test run
done

ra_test.erl:

-module(ra_test).

-export([run/0]).

%% RA Machine callbacks
-export([init/1, apply/3]).

run() ->
    {ok, _} = application:ensure_all_started(ra),
    Machine = {module, ?MODULE, #{}},
    Members = [{ra_test, node()}],
    {ok, [SrvId], []} = ra:start_cluster(ra_test, Machine, Members),
    ok = ra:stop_server(SrvId),
    ok = ra:restart_server(SrvId),
    do_test(SrvId),
    erlang:halt().

do_test(SrvId) ->
    case ra:process_command(SrvId, test_cmd) of
        {ok, ok, SrvId} ->
            ok;
        Else ->
            io:format("** ~p UNEXPECTED REPLY: ~p\n", [self(), Else]),
            io:format("** ~p\n", [sys:get_state(ra_test)]),
            receive
                continue ->
                    ok
            end
    end.

%% RA Machine callbacks
init(_) ->
    [].

apply(_Meta, test_cmd, S) ->
    {S, ok, []}.

Most of the time this works fine, but when it times out, it prints:

** <0.9.0> UNEXPECTED REPLY: {timeout,{ra_test,foo@lygna}}
** {follower,
       {state,
           {conf,"{ra_test,foo@lygna}",ra_test,ra_test,100,1000,30000,
               undefined,25,1000000,30000},
           #{aux_state => undefined,
             cluster =>
                 #{{ra_test,foo@lygna} =>
                       #{commit_index_sent => 0,match_index => 0,
                         next_index => 1,query_index => 0}},
             cluster_change_permitted => false,
             cluster_index_term => {0,0},
             commit_index => 0,commit_latency => 0,current_term => 1,
             effective_machine_module => ra_test,
             effective_machine_version => 0,
             id =>
                 {{ra_test,foo@lygna},
                  <<"RA_TESIRB3YEELDG9U">>,"{ra_test,foo@lygna}"},
             last_applied => 0, 
             log =>
                 {ra_log,<<"RA_TESIRB3YEELDG9U">>,"{ra_test,foo@lygna}",
                     "ra_dir/foo@lygna/RA_TESIRB3YEELDG9U",4096,
                     ra_log_snapshot,20,ra_log_wal,0,0,0,
                     {0,0},
                     {ra_snapshot,<<"RA_TESIRB3YEELDG9U">>,ra_log_snapshot,
                         "ra_dir/foo@lygna/RA_TESIRB3YEELDG9U/snapshots",
                         undefined,undefined,undefined},
                     #{},undefined,
                     {ra_log_reader,
                         {cfg,<<"RA_TESIRB3YEELDG9U">>,
                             "ra_dir/foo@lygna/RA_TESIRB3YEELDG9U"},
                         0,[],
                         {ra_flru,1,[],#Fun<ra_log_reader.0.104426489>}},
                     []},
             machine => {machine,ra_test,#{}},
             machine_state => [],machine_version => 0,
             machine_versions => [{0,0}],
             metrics_key => ra_test,pending_consistent_queries => [],
             persisted_last_applied => 0,
             queries_waiting_heartbeats => {[],[]},
             query_index => 0,
             voted_for => {ra_test,foo@lygna}},
           #{},
           [{{<0.137.0>,#Ref<0.456771077.4006871041.7816>},
             {command,normal,{'$usr',test_cmd,await_consensus}}}],
           undefined,undefined,
           {[],[]},
           false,0}}

I'm running Erlang/OTP 22.

[michaelklishin]

That's an interesting workload to test with.

We'd need node logs at debug level to suggest what may be going on, and Ra version used.

A cluster without a leader would not be able to process any commands. This is how Raft and Ra are expected to work.
We can assume that node state is indeed a follower and it never proceeds to win an election. The most recent known issue when that happened was addressed in #168.

It could also be that the machine state is not a good indication of what may be going on or that an election does succeed eventually.

[michaelklishin]

Closing because this is a question at this point. You are welcome to provide debug logs and if we can reproduce with 1.1.1, a more specific issue would be filed when we/if have a complete understanding.

[mbj4668]

I tested this with Ra 1.1.1, and I provided the program used to reproduce the issue.

I also tried with an 'infinity' timeout, and it hangs for a "long" time - are you suggesting that it may eventually become a leader? Note that it works most of the time, and that there's a single node only here.

Another hint is that if I remove the stop / restart functions, it seems the test always succeeds. (I've run it in a loop for many minutes)

[kjnilsson]

I will take a look at this scenario, debug logs would be very helpful if you can get them. Cheers.

[mbj4668]

I can get logs; what exactly should I do to get them? Any pointer?

[michaelklishin]

Having a program that supposedly reproduces the issue is useful but you already shared important bits of information that were never shared in the original post. So please do provide debug logs, they would immediately reveal a lot of things that would never be mentioned in an issue. Please help us help you.

If a timeout of infinity does not seemingly make any difference, it means the node does not complete/win the post-restart election. Our first hypothesis was that perhaps the default command timeout is insufficiently low and a leader election can take longer (Raft uses a randomized delay in leader elections after all).

[michaelklishin]

Ra uses the logger module in modern OTP. You have to set log level to debug and that should be it.

logger:set_primary_config(level, debug),
logger:info("info message"),
logger:debug("debug message").

Makes log entries printed to the shell.

logger:set_application_level(ra, debug).

should also work in case you get a lot of irrelevant output.

[mbj4668]

Here's the log (only debug for 'ra'):

2020-05-05T16:15:18.832641+02:00 debug: {ra_test,foo@lygna}: ra_log:init recovered last_index_term {0,0} first index 0
2020-05-05T16:15:18.845059+02:00 debug: {ra_test,foo@lygna}: recover -> recover in term: 0
2020-05-05T16:15:18.845281+02:00 debug: {ra_test,foo@lygna}: recovering state machine version 0:0 from index 0 to 0
2020-05-05T16:15:18.845541+02:00 debug: {ra_test,foo@lygna}: recover -> recovered in term: 0
2020-05-05T16:15:18.845761+02:00 debug: {ra_test,foo@lygna}: recovered -> follower in term: 0
2020-05-05T16:15:18.845965+02:00 debug: {ra_test,foo@lygna}: election triggered by <0.133.0>
2020-05-05T16:15:18.846137+02:00 debug: {ra_test,foo@lygna}: pre_vote election called for in term 0
2020-05-05T16:15:18.858047+02:00 debug: {ra_test,foo@lygna}: follower -> pre_vote in term: 0
2020-05-05T16:15:18.858216+02:00 debug: {ra_test,foo@lygna}: pre_vote granted #Ref<0.3467160107.3498573827.256429> for term 0 votes 1
2020-05-05T16:15:18.858326+02:00 debug: {ra_test,foo@lygna}: election called for in term 1
2020-05-05T16:15:18.870285+02:00 debug: {ra_test,foo@lygna}: pre_vote -> candidate in term: 1
2020-05-05T16:15:18.870499+02:00 notice: {ra_test,foo@lygna}: candidate -> leader in term: 1
2020-05-05T16:15:18.870728+02:00 info: ra: started cluster ra_test with 1 servers, 0 servers failed to start: [], Leader: {ra_test,foo@lygna}
2020-05-05T16:15:18.870951+02:00 info: {ra_test,foo@lygna}: terminating with shutdown in state leader
2020-05-05T16:15:18.871032+02:00 debug: {ra_test,foo@lygna}: terminating with reason 'shutdown'
2020-05-05T16:15:18.873366+02:00 debug: {ra_test,foo@lygna}: ra_log:init recovered last_index_term {0,0} first index 0
2020-05-05T16:15:18.880747+02:00 debug: {ra_test,foo@lygna}: recover -> recover in term: 1
2020-05-05T16:15:18.880876+02:00 debug: {ra_test,foo@lygna}: recovering state machine version 0:0 from index 0 to 0
2020-05-05T16:15:18.881043+02:00 debug: {ra_test,foo@lygna}: recover -> recovered in term: 1
2020-05-05T16:15:18.881205+02:00 debug: {ra_test,foo@lygna}: recovered -> follower in term: 1
2020-05-05T16:15:18.881362+02:00 info: {ra_test,foo@lygna}: leader call - leader not known. Command will be forwarded once leader is known.

Here's the last part (the only part that is different) of the log from a successful run:

2020-05-05T16:18:08.341445+02:00 info: {ra_test,foo@lygna}: terminating with shutdown in state leader
2020-05-05T16:18:08.341486+02:00 debug: {ra_test,foo@lygna}: terminating with reason 'shutdown'
2020-05-05T16:18:08.342878+02:00 debug: {ra_test,foo@lygna}: ra_log:init recovered last_index_term {1,1} first index 0
2020-05-05T16:18:08.345880+02:00 debug: {ra_test,foo@lygna}: recover -> recover in term: 1
2020-05-05T16:18:08.345946+02:00 debug: {ra_test,foo@lygna}: recovering state machine version 0:0 from index 0 to 0
2020-05-05T16:18:08.346027+02:00 debug: {ra_test,foo@lygna}: recover -> recovered in term: 1
2020-05-05T16:18:08.346106+02:00 debug: {ra_test,foo@lygna}: recovered -> follower in term: 1
2020-05-05T16:18:08.346158+02:00 debug: {ra_test,foo@lygna}: is not new, setting election timeout.
2020-05-05T16:18:08.346208+02:00 info: {ra_test,foo@lygna}: leader call - leader not known. Command will be forwarded once leader is known.

[kjnilsson]

ok so the difference there is a case where for some reason the election timeout isn't set after it enters follower state, presumably because it doesn't think it's got a log. I've got a test that does the same scenario but not managed to reproduce - can you dump the contents of the ra_log_open_mem_tables ETS table on failure? I'd like to see what is in it

[kjnilsson]

nope, scratch that, I've worked it out. The problem is that in your tests you sometimes managed to shut the server down before it has elected itself as a leader which means next time it starts it thinks it is a new server. Ra takes the approach that new servers do not automatically trigger elections, for a newly started server (using ra:start_server) you have then trigger the election using ra:trigger_election - alternatively in your test wait for the server to become leader before shutting it down, perhaps by using ra:members/1

[mbj4668]

Aha, great, thanks!

Once the cluster(s) are created, I'm trying to figure out how to best start the servers in case of node restarts. At the moment I call ra:restart_server on each node (3 or 5). From what you write above it seems I need to call ra:trigger_election after that, on each node (perhaps the previous leader is now down). Is that the correct way to start servers?