Server does not handle an undefined value in make_rpc_effect

[gianluca-nitti]

Describe the bug

I got this error while stress testing an application using ra:

08:56:10.866 [error] :gen_statem :server_ra_kv_partition_1 terminating
** (stop) {:EXIT, {{:case_clause, :undefined}, [{:ra_server, :make_rpc_effect, 5, [file: ~c"/app/deps/ra/src/ra_server.erl", line: 2140]}, {:ra_server, :"-make_pipelined_rpc_effects/3-fun-0-", 9, [file: ~c"/app/deps/ra/src/ra_server.erl", line: 2087]}, {:maps, :fold_1, 4, [file: ~c"maps.erl", line: 416]}, {:ra_server, :handle_leader, 2, [file: ~c"/app/deps/ra/src/ra_server.erl", line: 621]}, {:ra_server_proc, :handle_leader, 2, [file: ~c"/app/deps/ra/src/ra_server_proc.erl", line: 1161]}, {:ra_server_proc, :leader, 3, [file: ~c"/app/deps/ra/src/ra_server_proc.erl", line: 455]}, {:gen_statem, :loop_state_callback, 11, [file: ~c"gen_statem.erl", line: 1395]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 241]}]}}
    (ra 2.16.2) /app/deps/ra/src/ra_server_proc.erl:1172: :ra_server_proc.handle_leader/2
    (ra 2.16.2) /app/deps/ra/src/ra_server_proc.erl:455: :ra_server_proc.leader/3
    (stdlib 5.2.3.1) gen_statem.erl:1395: :gen_statem.loop_state_callback/11
    (stdlib 5.2.3.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
Queue: [{{:call, {#PID<0.1952.0>, [:alias | #Reference<0.0.249859.1325266628.2247163906.169031>]}}, {:leader_call, {:command, :normal, {:"$usr", {:set, {:access_tokens, "3nRiVvVNpv5nYlh82LzX9BYigJnqIX7TF8BuvXlQCinzPU/q2IjaMI61dYzX4+1g"}, %GianoAuth.Oauth.Token.AccessToken{code: "3nRiVvVNpv5nYlh82LzX9BYigJnqIX7TF8BuvXlQCinzPU/q2IjaMI61dYzX4+1g", type: :token, resource_owner: "[email protected]", expires_in: 3600, created_at: ~U[2025-03-04 08:56:00.863178Z], revoked_at: nil}, 3600000}, :await_consensus}}}}]
Postponed: []
State: {:leader, [id: {:server_ra_kv_partition_1, :"[email protected]"}, raft_state: :leader, leader_last_seen: :undefined, num_pending_commands: 0, num_low_priority_commands: 0, num_pending_applied_notifications: 0, election_timeout_set: false, ra_server_state: %{id: {:server_ra_kv_partition_1, :"[email protected]"}, machine: %{data: %{... redacted ...}, name: :server_ra_kv_partition_1, version: 0, __struct__: RaKv.Ra.Machine, machine_version: 0}, log: %{type: :ra_log, open_segments: 0, snapshot_index: :undefined, last_index: 11, num_segments: 1, first_index: 0, last_term: 1, last_wal_write: 1741078462596, last_written_index_term: {11, 1}, latest_checkpoint_index: :undefined, mem_table_info: %{name: :ra_mem_table, size: 1, tid: #Reference<0.1325266628.2247229442.120321>, range: :undefined, has_previous: false}, mem_table_range: :undefined, segments_range: {0, 11}, snapshot_term: :undefined}, aux: :undefined, membership: :voter, counter: {:write_concurrency, #Reference<0.1325266628.2247229442.120311>}, last_applied: 11, commit_index: 11, effective_machine_version: 0, uid: "Z2TMU2TEFYLABBGICM2AXM3WXHRZWZYH", system_config: %{message_queue_data: :off_heap, name: :giano_kv, names: %{directory: :ra_giano_kv_directory, directory_rev: :ra_giano_kv_directory_reverse, log_ets: :ra_giano_kv_log_ets, log_meta: :ra_giano_kv_log_meta, log_sup: :ra_giano_kv_log_sup, open_mem_tbls: :ra_giano_kv_log_open_mem_tables, segment_writer: :ra_giano_kv_segment_writer, server_sup: :ra_giano_kv_server_sup_sup, wal: :ra_giano_kv_log_wal, wal_sup: :ra_giano_kv_log_wal_sup}, data_dir: ~c"/tmp/giano_kv/ra_kv/giano_kv", segment_max_entries: 65536, wal_max_batch_size: 4096, wal_max_size_bytes: 1048576, wal_data_dir: ~c"/tmp/giano_kv/ra_kv/giano_kv", segment_max_pending: 1024, segment_compute_checksums: true, wal_compute_checksums: true, wal_max_entries: :undefined, wal_write_strategy: :default, wal_sync_method: :datasync, wal_garbage_collect: false, wal_pre_allocate: false, wal_min_bin_vheap_size: 46422, wal_min_heap_size: 233, server_min_heap_size: 233, server_min_bin_vheap_size: 46422, default_max_pipeline_count: 4096, default_max_append_entries_rpc_batch_size: 128, compress_mem_tables: false, snapshot_chunk_size: 1000000, receive_snapshot_timeout: 30000, low_priority_commands_flush_size: 16, low_priority_commands_in_memory_size: 16, machine_upgrade_strategy: :all}, log_id: ~c"{server_ra_kv_partition_1,'[email protected]'}", cluster: %{{:server_ra_kv_partition (truncated)

Looking at the code we realized that indeed this case block has no clause to match undefined despite the spec for ra_log:snapshot_index_term/1 also includes that atom in the return type.

Reproduction steps

Unfortunately I am not able to deterministically reproduce it. It has happened a couple of times while frequently making calls to a ra server, with a ra machine running on a cluster of 2 nodes.

Expected behavior

Server should not crash.

Additional context

No response

[kjnilsson]

the reason there is no handling of the undefined case is that in this case that is an invalid state. Something is wrong, either with the state on disk or the state maintaining the peer's next index.

Sharing the server's on disk state could be helpful. Also exactly which version of Ra you are using.

[michaelklishin]

@gianluca-nitti an exception in your app does not necessarily mean a problem in Ra. We cannot suggest anything without seeing your code and having a way to reproduce.

I'm afraid you will have to investigate this on your own and find a way to reduce it down to an executable test [case].

[flaviogrossi]

i've been able to somehow reproduce this and it seems that it was caused by segment_max_entries being set to 65536, which, according to this is not a valid value.
Does this sound plausible?

in my opinion a validation of the options like the one in the link above should be added to ra or at least documented better

[michaelklishin]

We don't have enough information to confidently suggest whether an invalid ra.segment_max_entries can be the root cause.

You are welcome to contribute better validation on Ra startup. That said, this are of Ra is undergoing changes right now so I'd wait for a month or so.