Fuzzing redisraft crash and assertion failure

[ds-testing-user]

We are a group of researchers testing distributed protocol implementations. While testing redisraft, we encountered the following crash (with a 3 node cluster).

logs for node: 1

----- Stdout -----
1459572:C 17 Oct 2023 23:52:55.110 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
1459572:C 17 Oct 2023 23:52:55.110 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1459572:C 17 Oct 2023 23:52:55.110 * Redis version=255.255.255, bits=64, commit=e04ebdb8, modified=1, pid=1459572, just started
1459572:C 17 Oct 2023 23:52:55.110 * Configuration loaded
1459572:M 17 Oct 2023 23:52:55.110 * monotonic clock: POSIX clock_gettime
1459572:M 17 Oct 2023 23:52:55.111 * Running mode=standalone, port=5091.
1459572:M 17 Oct 2023 23:52:55.115 * <raft> RedisRaft version 255.255.255 [c259f3d2]
1459572:M 17 Oct 2023 23:52:55.119 * <raft> Initializing test network
1459572:M 17 Oct 2023 23:52:55.120 * <raft> Created test network client
1459572:M 17 Oct 2023 23:52:55.123 * <raft> Raft module loaded, state is 'loading'
1459572:M 17 Oct 2023 23:52:55.123 * Module 'raft' loaded from /Fuzzing/redisraft-fuzzing/redisraft.so
1459572:M 17 Oct 2023 23:52:55.123 * Server initialized
1459572:M 17 Oct 2023 23:52:55.123 . The AOF directory appendonlydir doesn't exist
1459572:M 17 Oct 2023 23:52:55.123 * Ready to accept connections tcp
1459572:M 17 Oct 2023 23:52:55.123 . 0 clients connected (0 replicas), 1746720 bytes in use
1459572:M 17 Oct 2023 23:52:55.223 * <raft> Loading: Redis loading complete, snapshot NOT LOADED
1459572:M 17 Oct 2023 23:52:55.224 * <raft> Cluster Membership: term:0 index:0 nodes: id=1,voting=0,active=1,addr=-
1459572:M 17 Oct 2023 23:52:55.225 * <raft> Test network starting message polling thread
1459572:M 17 Oct 2023 23:52:55.225 * <raft> Cluster Membership: term:0 index:7 nodes: id=1,voting=1,active=1,addr=- id=2,voting=0,active=1,addr=localhost:5092
1459572:M 17 Oct 2023 23:52:55.225 * <raft> Cluster Membership: term:0 index:7 nodes: id=1,voting=1,active=1,addr=- id=2,voting=0,active=1,addr=localhost:5092 id=3,voting=0,active=1,addr=localhost:5093
1459572:M 17 Oct 2023 23:52:55.225 * <raft> Raft state after loading log: log_count=7, first_idx=1, current_idx=7, last_applied_idx=0
1459572:M 17 Oct 2023 23:52:55.225 . <raft> Raft term=1, vote=-1

----- Stderr -----




logs for node: 2

----- Stdout -----
1459989:C 17 Oct 2023 23:52:55.599 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
1459989:C 17 Oct 2023 23:52:55.599 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1459989:C 17 Oct 2023 23:52:55.599 * Redis version=255.255.255, bits=64, commit=e04ebdb8, modified=1, pid=1459989, just started
1459989:C 17 Oct 2023 23:52:55.599 * Configuration loaded
1459989:M 17 Oct 2023 23:52:55.600 * monotonic clock: POSIX clock_gettime
1459989:M 17 Oct 2023 23:52:55.600 * Running mode=standalone, port=5092.
1459989:M 17 Oct 2023 23:52:55.604 * <raft> RedisRaft version 255.255.255 [c259f3d2]
1459989:M 17 Oct 2023 23:52:55.608 * <raft> Initializing test network
1459989:M 17 Oct 2023 23:52:55.609 * <raft> Created test network client
1459989:M 17 Oct 2023 23:52:55.612 * <raft> Raft module loaded, state is 'loading'
1459989:M 17 Oct 2023 23:52:55.612 * Module 'raft' loaded from /Fuzzing/redisraft-fuzzing/redisraft.so
1459989:M 17 Oct 2023 23:52:55.613 * Server initialized
1459989:M 17 Oct 2023 23:52:55.613 . The AOF directory appendonlydir doesn't exist
1459989:M 17 Oct 2023 23:52:55.613 * Ready to accept connections tcp
1459989:M 17 Oct 2023 23:52:55.613 . 0 clients connected (0 replicas), 1746656 bytes in use

----- Stderr -----




logs for node: 3

----- Stdout -----
1458964:C 17 Oct 2023 23:52:54.464 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
1458964:C 17 Oct 2023 23:52:54.464 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1458964:C 17 Oct 2023 23:52:54.464 * Redis version=255.255.255, bits=64, commit=e04ebdb8, modified=1, pid=1458964, just started
1458964:C 17 Oct 2023 23:52:54.464 * Configuration loaded
1458964:M 17 Oct 2023 23:52:54.464 * monotonic clock: POSIX clock_gettime
1458964:M 17 Oct 2023 23:52:54.465 * Running mode=standalone, port=5093.
1458964:M 17 Oct 2023 23:52:54.469 * <raft> RedisRaft version 255.255.255 [c259f3d2]
1458964:M 17 Oct 2023 23:52:54.473 * <raft> Initializing test network
1458964:M 17 Oct 2023 23:52:54.474 * <raft> Created test network client
1458964:M 17 Oct 2023 23:52:54.478 * <raft> Raft module loaded, state is 'loading'
1458964:M 17 Oct 2023 23:52:54.478 * Module 'raft' loaded from /Fuzzing/redisraft-fuzzing/redisraft.so
1458964:M 17 Oct 2023 23:52:54.478 * Server initialized
1458964:M 17 Oct 2023 23:52:54.478 . The AOF directory appendonlydir doesn't exist
1458964:M 17 Oct 2023 23:52:54.478 * Ready to accept connections tcp
1458964:M 17 Oct 2023 23:52:54.478 . 0 clients connected (0 replicas), 1746816 bytes in use
1458964:M 17 Oct 2023 23:52:54.578 * <raft> Loading: Redis loading complete, snapshot NOT LOADED
1458964:M 17 Oct 2023 23:52:54.579 * <raft> Cluster Membership: term:0 index:0 nodes: id=3,voting=0,active=1,addr=-
1458964:M 17 Oct 2023 23:52:54.580 * <raft> Test network starting message polling thread
1458964:M 17 Oct 2023 23:52:54.580 * <raft> Cluster Membership: term:0 index:6 nodes: id=3,voting=0,active=1,addr=- id=1,voting=1,active=1,addr=localhost:5091
1458964:M 17 Oct 2023 23:52:54.580 * <raft> Cluster Membership: term:0 index:6 nodes: id=3,voting=0,active=1,addr=- id=1,voting=1,active=1,addr=localhost:5091 id=2,voting=0,active=1,addr=localhost:5092
1458964:M 17 Oct 2023 23:52:54.580 * <raft> Raft state after loading log: log_count=6, first_idx=1, current_idx=6, last_applied_idx=0
1458964:M 17 Oct 2023 23:52:54.580 . <raft> Raft term=1, vote=-1


=== REDIS BUG REPORT START: Cut & paste starting from here ===
1458964:M 17 Oct 2023 23:52:54.679 # === ASSERTION FAILED ===
1458964:M 17 Oct 2023 23:52:54.679 # ==> /Fuzzing/redisraft-fuzzing/src/raft.c:2184 'e == 0' is not true

------ STACK TRACE ------

Backtrace:
/Fuzzing/redisraft-fuzzing/redisraft.so(handleBeforeSleep+0xd4)[0x7fa76ab139c4]
/Fuzzing/redis/src/redis-server 0.0.0.0:5093(moduleFireServerEvent+0x1f5)[0x558637f7df05]
/Fuzzing/redis/src/redis-server 0.0.0.0:5093(beforeSleep+0x416)[0x558637e8cc56]
/Fuzzing/redis/src/redis-server 0.0.0.0:5093(aeMain+0x2e)[0x558637e87b1e]
/Fuzzing/redis/src/redis-server 0.0.0.0:5093(main+0x3cd)[0x558637e7ce2d]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xea)[0x7fa76ab96d0a]
/Fuzzing/redis/src/redis-server 0.0.0.0:5093(_start+0x2a)[0x558637e7d5aa]

------ INFO OUTPUT ------
# Server
redis_version:255.255.255
redis_git_sha1:e04ebdb8
redis_git_dirty:1
redis_build_id:1f78dcc7b4fbdd25
redis_mode:standalone
os:Linux 5.15.111.1.amd64-smp x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
atomicvar_api:c11-builtin
gcc_version:10.2.1
process_id:1458964
process_supervised:no
run_id:d6cdc6a56407fcdb1e6af4b17610722470a06696
tcp_port:5093
server_time_usec:1697579574679619
uptime_in_seconds:0
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:3080758
executable:/Fuzzing/redis/src/redis-server
config_file:
io_threads_active:0
listener0:name=tcp,bind=0.0.0.0,port=5093

# Clients
connected_clients:0
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
total_blocking_keys:0
total_blocking_keys_on_nokey:0

# Memory
used_memory:1756040
used_memory_human:1.67M
used_memory_rss:15495168
used_memory_rss_human:14.78M
used_memory_peak:1756040
used_memory_peak_human:1.67M
used_memory_peak_perc:100.11%
used_memory_overhead:1746856
used_memory_startup:1746672
used_memory_dataset:9184
used_memory_dataset_perc:98.04%
allocator_allocated:2266552
allocator_active:2822144
allocator_resident:10969088
total_system_memory:270386737152
total_system_memory_human:251.82G
used_memory_lua:31744
used_memory_vm_eval:31744
used_memory_lua_human:31.00K
used_memory_scripts_eval:0
number_of_cached_scripts:0
number_of_functions:0
number_of_libraries:0
used_memory_vm_functions:32768
used_memory_vm_total:64512
used_memory_vm_total_human:63.00K
used_memory_functions:184
used_memory_scripts:184
used_memory_scripts_human:184B
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.25
allocator_frag_bytes:555592
allocator_rss_ratio:3.89
allocator_rss_bytes:8146944
rss_overhead_ratio:1.41
rss_overhead_bytes:4526080
mem_fragmentation_ratio:8.83
mem_fragmentation_bytes:13741048
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_total_replication_buffers:0
mem_clients_slaves:0
mem_clients_normal:0
mem_cluster_links:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.3.0
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0

# Persistence
loading:0
async_loading:0
current_cow_peak:0
current_cow_size:0
current_cow_size_age:0
current_fork_perc:0.00
current_save_keys_processed:0
current_save_keys_total:0
rdb_changes_since_last_save:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1697579574
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_saves:0
rdb_last_cow_size:0
rdb_last_load_keys_expired:0
rdb_last_load_keys_loaded:0
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_rewrites:0
aof_rewrites_consecutive_failures:0
aof_last_write_status:ok
aof_last_cow_size:0
module_fork_in_progress:0
module_fork_last_cow_size:0

# Stats
total_connections_received:0
total_commands_processed:6
instantaneous_ops_per_sec:26
total_net_input_bytes:0
total_net_output_bytes:0
total_net_repl_input_bytes:0
total_net_repl_output_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
instantaneous_input_repl_kbps:0.00
instantaneous_output_repl_kbps:0.00
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
evicted_clients:0
total_eviction_exceeded_time:0
current_eviction_exceeded_time:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
pubsubshard_channels:0
latest_fork_usec:0
total_forks:0
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0
total_active_defrag_time:0
current_active_defrag_time:0
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:0
dump_payload_sanitizations:0
total_reads_processed:0
total_writes_processed:0
io_threaded_reads_processed:0
io_threaded_writes_processed:0
reply_buffer_shrinks:0
reply_buffer_expands:0
acl_access_denied_auth:0
acl_access_denied_cmd:0
acl_access_denied_key:0
acl_access_denied_channel:0

# Replication
role:master
connected_slaves:0
master_failover_state:no-failover
master_replid:f897fdb8aca52701d079f069164cc4cda308dffe
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:0.005059
used_cpu_user:0.017760
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
used_cpu_sys_main_thread:0.005165
used_cpu_user_main_thread:0.010330

# Modules
module:name=raft,ver=1,api=1,filters=1,usedby=[],using=[],options=[]

# Commandstats
cmdstat_config|get:calls=3,usec=6,usec_per_call=2.00,rejected_calls=0,failed_calls=0
cmdstat_config|set:calls=1,usec=6,usec_per_call=6.00,rejected_calls=0,failed_calls=0
cmdstat_command:calls=2,usec=1436,usec_per_call=718.00,rejected_calls=0,failed_calls=0

# Errorstats

# Latencystats
latency_percentiles_usec_config|get:p50=2.007,p99=3.007,p99.9=3.007
latency_percentiles_usec_config|set:p50=6.015,p99=6.015,p99.9=6.015
latency_percentiles_usec_command:p50=667.647,p99=770.047,p99.9=770.047

# Cluster
cluster_enabled:0

# Keyspace

------ CLIENT LIST OUTPUT ------

------ MODULES INFO OUTPUT ------
# raft_version
raft_version:255.255.255
raft_git_sha1:c259f3d2

# raft_general
raft_dbid:bf04b0ed0bf8b23d38d8763115c4a63e
raft_node_id:3
raft_state:up
raft_role:follower
raft_is_voting:yes
raft_voted_for:-1
raft_leader_id:1
raft_current_term:1
raft_num_nodes:3
raft_num_voting_nodes:2
raft_node1:id=1,state=connect_error,voting=yes,addr=localhost,port=5091,last_conn_secs=-1,conn_errors=1,conn_oks=0
raft_node2:id=2,state=disconnected,voting=no,addr=localhost,port=5092,last_conn_secs=0,conn_errors=0,conn_oks=1

# raft_log
raft_log_entries:6
raft_current_index:6
raft_commit_index:6
raft_last_applied_index:2
raft_file_size:1638
raft_cache_memory_size:0
raft_cache_entries:0
raft_client_attached_entries:0
raft_fsync_count:0
raft_fsync_max_microseconds:0
raft_fsync_avg_microseconds:0

# raft_snapshot
raft_snapshot_filename:redis3.rdb
raft_snapshot_last_idx:0
raft_snapshot_last_term:0
raft_snapshot_size:0
raft_snapshot_time_secs:-1
raft_snapshots_created:0
raft_snapshots_received:0
raft_snapshot_in_progress:no
raft_snapshot_in_progress_last_idx:-1
raft_snapshot_in_progress_last_term:-1

# raft_clients
raft_proxy_reqs:0
raft_proxy_failed_reqs:0
raft_proxy_failed_responses:0
raft_proxy_outstanding_reqs:0

# raft_stats
raft_appendreq_received:0
raft_appendreq_with_entry_received:0
raft_snapshotreq_received:0
raft_exec_throttled:0
raft_num_sessions:0

------ CONFIG DEBUG OUTPUT ------
lazyfree-lazy-user-del no
repl-diskless-sync yes
lazyfree-lazy-expire no
repl-diskless-load disabled
list-compress-depth 0
replica-read-only yes
proto-max-bulk-len 512mb
io-threads 1
lazyfree-lazy-eviction no
sanitize-dump-payload no
slave-read-only yes
lazyfree-lazy-user-flush no
io-threads-do-reads no
activedefrag no
lazyfree-lazy-server-del no
client-query-buffer-limit 1gb

------ FAST MEMORY TEST ------
1458964:M 17 Oct 2023 23:52:54.680 # Bio worker thread #0 terminated
1458964:M 17 Oct 2023 23:52:54.680 # Bio worker thread #1 terminated
1458964:M 17 Oct 2023 23:52:54.680 # Bio worker thread #2 terminated
*** Preparing to test memory region 558638153000 (2273280 bytes)
*** Preparing to test memory region 558639365000 (405504 bytes)
*** Preparing to test memory region 7fa734000000 (135168 bytes)
*** Preparing to test memory region 7fa738000000 (135168 bytes)
*** Preparing to test memory region 7fa73c000000 (135168 bytes)
*** Preparing to test memory region 7fa744000000 (135168 bytes)
*** Preparing to test memory region 7fa748000000 (135168 bytes)
*** Preparing to test memory region 7fa74e400000 (2097152 bytes)
*** Preparing to test memory region 7fa74efff000 (8388608 bytes)
*** Preparing to test memory region 7fa74f800000 (8388608 bytes)
*** Preparing to test memory region 7fa750000000 (135168 bytes)
*** Preparing to test memory region 7fa754000000 (135168 bytes)
*** Preparing to test memory region 7fa758000000 (135168 bytes)
*** Preparing to test memory region 7fa75c1fb000 (2097152 bytes)
*** Preparing to test memory region 7fa75cbfd000 (8388608 bytes)
*** Preparing to test memory region 7fa75d3fd000 (4194304 bytes)
*** Preparing to test memory region 7fa75d7fe000 (8388608 bytes)
*** Preparing to test memory region 7fa75dfff000 (8388608 bytes)
*** Preparing to test memory region 7fa75e800000 (8388608 bytes)
*** Preparing to test memory region 7fa75f000000 (6291456 bytes)
*** Preparing to test memory region 7fa75f7f8000 (8388608 bytes)
*** Preparing to test memory region 7fa75fff9000 (8388608 bytes)
*** Preparing to test memory region 7fa7607fa000 (8388608 bytes)
*** Preparing to test memory region 7fa760ffb000 (8388608 bytes)
*** Preparing to test memory region 7fa7617fc000 (8388608 bytes)
*** Preparing to test memory region 7fa761ffd000 (8388608 bytes)
*** Preparing to test memory region 7fa7627fe000 (8388608 bytes)
*** Preparing to test memory region 7fa762fff000 (8388608 bytes)
*** Preparing to test memory region 7fa763800000 (8388608 bytes)
*** Preparing to test memory region 7fa764000000 (135168 bytes)
*** Preparing to test memory region 7fa768000000 (4194304 bytes)
*** Preparing to test memory region 7fa768566000 (8388608 bytes)
*** Preparing to test memory region 7fa768d66000 (2621440 bytes)
*** Preparing to test memory region 7fa769077000 (8192 bytes)
*** Preparing to test memory region 7fa7690b7000 (4096 bytes)
*** Preparing to test memory region 7fa7696e5000 (8192 bytes)
*** Preparing to test memory region 7fa769938000 (8192 bytes)
*** Preparing to test memory region 7fa76a200000 (8388608 bytes)
*** Preparing to test memory region 7fa76aaad000 (4096 bytes)
*** Preparing to test memory region 7fa76ab68000 (45056 bytes)
*** Preparing to test memory region 7fa76ad43000 (16384 bytes)
*** Preparing to test memory region 7fa76ad65000 (16384 bytes)
*** Preparing to test memory region 7fa76aeb3000 (8192 bytes)
*** Preparing to test memory region 7fa76aeb7000 (4096 bytes)
*** Preparing to test memory region 7fa76aed4000 (4096 bytes)
*** Preparing to test memory region 7fa76af15000 (4096 bytes)
*** Preparing to test memory region 7fa76af18000 (4096 bytes)
.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O
Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.

=== REDIS BUG REPORT END. Make sure to include from START to END. ===

       Please report the crash by opening an issue on github:

           http:https://github.com/redis/redis/issues

  If a Redis module was involved, please open in the module's repo instead.

  Suspect RAM error? Use redis-server --test-memory to verify it.

  Some other issues could be detected by redis-server --check-system

----- Stderr -----

We have been able to reproduce the error on multiple machines.