KeyDB 6.0.9 - Adding a read only replica to active-active breaks replica

[Unaidedsteak]

Describe the bug
When setting up and active-active cluster, we'd like to have a read only slave attached to the "cluster", primarily for DR or further fault tolerance.
When starting the read-only slave, the process crashes with a SIGSEGV

** Log Files **
24910:24909:S 12 Aug 2020 11:34:36.499 # Server initialized
24910:24909:S 12 Aug 2020 11:34:36.499 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with KeyDB. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. KeyDB must be restarted after THP is disabled.
24910:24917:S 12 Aug 2020 11:34:36.500 Thread 0 alive.
24910:24918:S 12 Aug 2020 11:34:36.500 Thread 1 alive.
24910:24917:S 12 Aug 2020 11:34:36.500 * Connecting to MASTER 10.119.0.11:6379
24910:24917:S 12 Aug 2020 11:34:36.500 * MASTER <-> REPLICA sync started
24910:24917:S 12 Aug 2020 11:34:36.502 * Non blocking connect for SYNC fired the event.
24910:24917:S 12 Aug 2020 11:34:36.502 * Master replied to PING, replication can continue...
24910:24917:S 12 Aug 2020 11:34:36.503 * Trying a partial resynchronization (request 7670e27be4967e208caaf2a999b75787a66d8d71:1).
24910:24917:S 12 Aug 2020 11:34:36.505 * Full resync from master: a21b2de4a442eba5a249c49998a920a12eac907f:5143699
24910:24917:S 12 Aug 2020 11:34:36.505 * Discarding previously cached master state.
24910:24917:S 12 Aug 2020 11:34:36.594 * MASTER <-> REPLICA sync: receiving 1141 bytes from master to disk
24910:24917:S 12 Aug 2020 11:34:36.594 * MASTER <-> REPLICA sync: Flushing old data
24910:24917:S 12 Aug 2020 11:34:36.594 * MASTER <-> REPLICA sync: Loading DB in memory
24910:24917:S 12 Aug 2020 11:34:36.594 * Loading RDB produced by version 6.0.9
24910:24917:S 12 Aug 2020 11:34:36.594 * RDB age 0 seconds
24910:24917:S 12 Aug 2020 11:34:36.594 * RDB memory usage when created 18.06 Mb
24910:24917:S 12 Aug 2020 11:34:36.594 * MASTER <-> REPLICA sync: Finished with success

=== KEYDB BUG REPORT START: Cut & paste starting from here ===
24910:24917:S 12 Aug 2020 11:34:36.597 # KeyDB 6.0.9 crashed by signal: 11
24910:24917:S 12 Aug 2020 11:34:36.597 # Crashed running the instruction at: 0x7fbc16bdc06f
24910:24917:S 12 Aug 2020 11:34:36.597 # Accessing address: 0x7fbc12400000
24910:24917:S 12 Aug 2020 11:34:36.597 # Failed assertion: (:0)

------ STACK TRACE ------
EIP:
/lib/x86_64-linux-gnu/libc.so.6(+0x12906f) [0x7fbc16bdc06f]

Backtrace:
/usr/bin/keydb-server 0.0.0.0:6379(logStackTrace(ucontext*)+0x45) [0x563b60e6bff5]
/usr/bin/keydb-server 0.0.0.0:6379(sigsegvHandler(int, siginfo_t*, void*)+0xdb) [0x563b60e6c7bb]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110e0) [0x7fbc16e630e0]
/lib/x86_64-linux-gnu/libc.so.6(+0x12906f) [0x7fbc16bdc06f]
/usr/bin/keydb-server 0.0.0.0:6379(feedReplicationBacklog(void const*, unsigned long)+0x87) [0x563b60e3b9f7]
/usr/bin/keydb-server 0.0.0.0:6379(replicationFeedSlavesFromMasterStream(list*, char*, unsigned long)+0x41) [0x563b60e414f1]
/usr/bin/keydb-server 0.0.0.0:6379(commandProcessed(client*)+0xeb) [0x563b60e1fa2b]
/usr/bin/keydb-server 0.0.0.0:6379(processCommandAndResetClient(client*, int)+0x90) [0x563b60e1fb90]
/usr/bin/keydb-server 0.0.0.0:6379(processInputBuffer(client*, int)+0x18b) [0x563b60e24ccb]
/usr/bin/keydb-server 0.0.0.0:6379(replicaReplayCommand(client*)+0x570) [0x563b60e44d00]
/usr/bin/keydb-server 0.0.0.0:6379(call(client*, int)+0xd0) [0x563b60e101a0]
/usr/bin/keydb-server 0.0.0.0:6379(processCommand(client*, int, AeLocker&)+0xba4) [0x563b60e14b54]
/usr/bin/keydb-server 0.0.0.0:6379(processCommandAndResetClient(client*, int)+0x3b) [0x563b60e1fb3b]
/usr/bin/keydb-server 0.0.0.0:6379(processInputBuffer(client*, int)+0x18b) [0x563b60e24ccb]
/usr/bin/keydb-server 0.0.0.0:6379(readQueryFromClient(connection*)+0x3dd) [0x563b60e27d7d]
/usr/bin/keydb-server 0.0.0.0:6379(+0x10ca85) [0x563b60ec8a85]
/usr/bin/keydb-server 0.0.0.0:6379(ProcessEventCore+0x19e) [0x563b60e07f9e]
/usr/bin/keydb-server 0.0.0.0:6379(aeProcessEvents+0x205) [0x563b60e08255]
/usr/bin/keydb-server 0.0.0.0:6379(aeMain+0x45) [0x563b60e08705]
/usr/bin/keydb-server 0.0.0.0:6379(workerThreadMain(void*)+0x6a) [0x563b60e0efea]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x74a4) [0x7fbc16e594a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fbc16b9bd0f]

------ INFO OUTPUT ------

Server

redis_version:6.0.9
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:fd315cec7f3f3a05
redis_mode:standalone
os:Linux 4.9.0-12-amd64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:6.3.0
process_id:24910
run_id:8712abe202ae472b5f0e8f588ab6780bcf469e1d
tcp_port:6379
uptime_in_seconds:0
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:3396556
executable:/usr/bin/keydb-server
config_file:/etc/keydb/keydb.conf

Clients

connected_clients:1
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
current_client_thread:0
thread_0_clients:1
thread_1_clients:0

Memory

used_memory:18875272
used_memory_human:18.00M
used_memory_rss:21983232
used_memory_rss_human:20.96M
used_memory_peak:18875272
used_memory_peak_human:18.00M
used_memory_peak_perc:106.29%
used_memory_overhead:18812416
used_memory_startup:17758760
used_memory_dataset:62856
used_memory_dataset_perc:5.63%
allocator_allocated:18173064
allocator_active:18665472
allocator_resident:23232512
total_system_memory:7847464960
total_system_memory_human:7.31G
used_memory_lua:40960
used_memory_lua_human:40.00K
used_memory_scripts:264
used_memory_scripts_human:264B
number_of_cached_scripts:1
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.03
allocator_frag_bytes:492408
allocator_rss_ratio:1.24
allocator_rss_bytes:4567040
rss_overhead_ratio:0.95
rss_overhead_bytes:-1249280
mem_fragmentation_ratio:1.24
mem_fragmentation_bytes:4224376
mem_not_counted_for_evict:0
mem_replication_backlog:1048576
mem_clients_slaves:0
mem_clients_normal:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0

Persistence

loading:0
rdb_changes_since_last_save:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1597232076
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size: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_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:1
instantaneous_ops_per_sec:0
total_net_input_bytes:1973
total_net_output_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_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
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec: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
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0

Replication

role:slave
master_global_link_status:up
Master 0:
master_host:10.119.0.11
master_port:6379
master_link_status:up
master_last_io_seconds_ago:0
master_sync_in_progress:0
slave_repl_offset:5143699
slave_priority:100
slave_read_only:1
connected_slaves:0
master_replid:a21b2de4a442eba5a249c49998a920a12eac907f
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:5143561
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:5143700
repl_backlog_histlen:3145728

CPU

used_cpu_sys:0.012000
used_cpu_user:0.012000
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
server_threads:2
long_lock_waits:0

Modules

Commandstats

cmdstat_select:calls=1,usec=1,usec_per_call=1.00

Cluster

cluster_enabled:0

Keyspace

db0:keys=6,expires=6,avg_ttl=20618
db1:keys=2,expires=1,avg_ttl=240909

------ CLIENT LIST OUTPUT ------
id=5 addr=10.119.0.11:6379 fd=85 name= age=0 idle=0 flags=M db=0 sub=0 psub=0 multi=-1 qbuf=832 qbuf-free=31936 obl=0 oll=0 omem=0 events=r cmd=rreplay user=(superuser)

------ CURRENT CLIENT INFO ------

Please copy everything after this line.

To Reproduce

1. Setup an active-active pair, all running v6.0.9
2. Try adding a read only replica to one of the active nodes

[JohnSully]

Hey @Unaidedsteak

I wasn't able to repro the issue and the crash address doesn't make much sense. Could you give me an overview of your topology? Also by read only you mean the config "replica-read-only yes" correct?

[Unaidedsteak]

Hi @JohnSully

I do indeed mean "replica-read-only yes" for the read only replica, yes.
As for topology, nothing crazy going on:

All keydb nodes are runing debian 9, kernel 4.9.0-11
The active replica pair were setup following https://docs.keydb.dev/docs/active-rep/
The backup node as setup to just point to keydb-2 as a read only replica
All reads and writes go go keydb-1 with the ability to fail over to keydb-2 (currently just via a DNS switch)

Please let me know if there's any other information I can provide

[JohnSully]

Thanks I was able to repro. As a workaround if your backup has active replication enabled it will not crash. That said I'll work on a fix so that won't be required.

[JohnSully]

This was never supported before (although I didn't gate it either). However the scenario makes a lot of sense and so I've done the work to support this. In addition to the crash we also had to do some work to ensure expires actually occur.

[Unaidedsteak]

Thanks for you work on this @JohnSully! Any ideas on when we could expect this to be in a stable release?

[JohnSully]

Should be out later this week.