[CRASH] Random crash on decrRefCount after command completeion

[r00t3g]

Crash report

Paste the complete crash log between the quotes below. Please include a few lines from the log preceding the crash report to provide some context.

11058:11057:C 11 Apr 2023 12:05:06.088 # oO0OoO0OoO0Oo KeyDB is starting oO0OoO0OoO0Oo
11058:11057:C 11 Apr 2023 12:05:06.089 # KeyDB version=6.3.2, bits=64, commit=00000000, modified=0, pid=11058, just started
11058:11057:C 11 Apr 2023 12:05:06.089 # Configuration loaded
11058:11057:M 11 Apr 2023 12:05:06.091 * monotonic clock: POSIX clock_gettime
11058:11057:M 11 Apr 2023 12:05:06.092 * Node configuration loaded, I'm 064af590724248d2babf8e5d9bfd7fe4d7a9bc5d
11058:11057:M 11 Apr 2023 12:05:06.092 * Expanding min-clients-per-thread to 200 due to cluster
11058:11057:M 11 Apr 2023 12:05:06.092 * Running mode=cluster, port=6000.
11058:11057:M 11 Apr 2023 12:05:06.092 # Server initialized
11058:11067:M 11 Apr 2023 12:05:06.093 * Thread 0 alive.
11058:11069:M 11 Apr 2023 12:05:06.093 * Thread 1 alive.
11058:11067:S 11 Apr 2023 12:05:06.155 * Before turning into a replica, using my own master parameters to synthesize a cached master: I may be able to synchronize with the new master with just a partial transfer.
11058:11067:S 11 Apr 2023 12:05:06.155 * Connecting to MASTER 10.64.49.12:6008
11058:11067:S 11 Apr 2023 12:05:06.155 * MASTER <-> REPLICA sync started
11058:11067:S 11 Apr 2023 12:05:06.155 # Cluster state changed: ok
11058:11067:S 11 Apr 2023 12:05:06.158 * Non blocking connect for SYNC fired the event.
11058:11067:S 11 Apr 2023 12:05:06.161 * Master does not support REPLPING, sending PING instead...
11058:11067:S 11 Apr 2023 12:05:06.161 * Non blocking connect for SYNC fired the event.
11058:11067:S 11 Apr 2023 12:05:06.161 * Master replied to PING, replication can continue...
11058:11067:S 11 Apr 2023 12:05:06.161 # non-fatal: Master doesn't understand REPLCONF uuid
11058:11067:S 11 Apr 2023 12:05:06.161 * Trying a partial resynchronization (request eb5c82c4e5a04371643b1123fa5fe809f83a5d81:1).
11058:11067:S 11 Apr 2023 12:05:08.633 * Full resync from master: 57a7934ae9708681637a8ae20f3bda3b853ba41c:51985667563394
11058:11067:S 11 Apr 2023 12:05:08.633 * Discarding previously cached master state.
11058:11067:S 11 Apr 2023 12:05:09.627 * MASTER <-> REPLICA sync: receiving streamed RDB from master with EOF to disk
11058:11067:S 11 Apr 2023 12:07:13.830 * MASTER <-> REPLICA sync: Flushing old data
11058:11067:S 11 Apr 2023 12:07:13.830 * MASTER <-> REPLICA sync: Loading DB in memory
11058:11067:S 11 Apr 2023 12:07:13.845 * Loading RDB produced by version 5.0.8
11058:11067:S 11 Apr 2023 12:07:13.845 * RDB age 124 seconds
11058:11067:S 11 Apr 2023 12:07:13.845 * RDB memory usage when created 27238.78 Mb
11058:11067:S 11 Apr 2023 12:20:00.944 # Done loading RDB, keys loaded: 0, keys expired: 0.
11058:11067:S 11 Apr 2023 12:20:00.944 * MASTER <-> REPLICA sync: Finished with success
11058:11069:S 11 Apr 2023 12:54:12.862 # Manual failover user request accepted.
11058:11067:S 11 Apr 2023 12:54:12.895 # Received replication offset for paused master manual failover: 51986981234901
11058:11067:S 11 Apr 2023 12:54:12.895 # All master replication stream processed, manual failover can start.
11058:11067:S 11 Apr 2023 12:54:12.895 # Start of election delayed for 0 milliseconds (rank #0, offset 51986981234901).
11058:11069:S 11 Apr 2023 12:54:12.895 # Starting a failover election for epoch 360.
11058:11067:S 11 Apr 2023 12:54:12.902 # Currently unable to failover: Waiting for votes, but majority still not reached.
11058:11067:S 11 Apr 2023 12:54:12.903 # Failover election won: I'm the new master.
11058:11067:S 11 Apr 2023 12:54:12.903 # configEpoch set to 360 after successful failover
11058:11067:S 11 Apr 2023 12:54:12.903 # Connection with master lost.
11058:11067:S 11 Apr 2023 12:54:12.903 * Caching the disconnected master state.
11058:11067:S 11 Apr 2023 12:54:12.903 * Discarding previously cached master state.
11058:11067:S 11 Apr 2023 12:54:12.903 # Setting secondary replication ID to 57a7934ae9708681637a8ae20f3bda3b853ba41c, valid up to offset: 51986981234902. New replication ID is e1896072291a4348276a70c0df81229318eb0890
11058:11069:M 11 Apr 2023 12:54:12.909 * Replica 10.64.54.10:40012 asks for synchronization
11058:11069:M 11 Apr 2023 12:54:12.909 * Partial resynchronization request from 10.64.54.10:40012 accepted. Sending 20346 bytes of backlog starting from offset 51986981234902.
11058:11067:M 11 Apr 2023 12:54:12.977 * Replica 10.64.40.28:6001 asks for synchronization
11058:11067:M 11 Apr 2023 12:54:12.977 * Partial resynchronization request from 10.64.40.28:6001 accepted. Sending 447784 bytes of backlog starting from offset 51986981234902.
11058:11067:M 11 Apr 2023 12:54:13.063 * Replica 10.64.46.19:6005 asks for synchronization
11058:11067:M 11 Apr 2023 12:54:13.063 * Partial resynchronization request from 10.64.46.19:6005 accepted. Sending 1065606 bytes of backlog starting from offset 51986981234902.
11058:11069:M 11 Apr 2023 12:54:13.109 * Replica 10.64.56.5:40010 asks for synchronization
11058:11069:M 11 Apr 2023 12:54:13.109 * Partial resynchronization request from 10.64.56.5:40010 accepted. Sending 1376863 bytes of backlog starting from offset 51986981234902.
11058:11067:M 11 Apr 2023 12:54:13.114 * Replica 10.64.48.20:6006 asks for synchronization
11058:11067:M 11 Apr 2023 12:54:13.114 * Partial resynchronization request from 10.64.48.20:6006 accepted. Sending 1420738 bytes of backlog starting from offset 51986981234902.
11058:11067:M 11 Apr 2023 12:54:13.152 * Replica 10.64.49.12:6008 asks for synchronization
11058:11067:M 11 Apr 2023 12:54:13.152 * Partial resynchronization request from 10.64.49.12:6008 accepted. Sending 1671700 bytes of backlog starting from offset 51986981234902.
11058:11069:M 11 Apr 2023 12:54:13.749 * Replica 10.64.49.10:6007 asks for synchronization
11058:11069:M 11 Apr 2023 12:54:13.749 * Partial resynchronization request from 10.64.49.10:6007 accepted. Sending 5411634 bytes of backlog starting from offset 51986981234902.
11058:11069:M 11 Apr 2023 12:54:13.801 * Replica 10.64.37.6:6009 asks for synchronization
11058:11069:M 11 Apr 2023 12:54:13.801 * Partial resynchronization request from 10.64.37.6:6009 accepted. Sending 5735198 bytes of backlog starting from offset 51986981234902.
11058:11067:M 11 Apr 2023 15:43:30.059 * Marking node a6166d1d0562457b72544bacde53d1dfe3df24eb as failing (quorum reached).


=== KEYDB BUG REPORT START: Cut & paste starting from here ===
11058:11069:M 12 Apr 2023 07:07:28.819 # ------------------------------------------------
11058:11069:M 12 Apr 2023 07:07:28.819 # !!! Software Failure. Press left mouse button to continue
11058:11069:M 12 Apr 2023 07:07:28.820 # Guru Meditation: decrRefCount against refcount <= 0 #object.cpp:427

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

Backtrace:
/usr/local/bin/redis-server *:6000 [cluster](decrRefCount(robj_roptr)+0x195) [0x564315450255]
/usr/local/bin/redis-server *:6000 [cluster](+0x15ab48) [0x564315361b48]
/usr/local/bin/redis-server *:6000 [cluster](resetClient(client*)+0x24) [0x564315361ba4]
/usr/local/bin/redis-server *:6000 [cluster](commandProcessed(client*, int)+0x22) [0x5643153630b2]
/usr/local/bin/redis-server *:6000 [cluster](processCommandAndResetClient(client*, int)+0x11a) [0x56431536334a]
/usr/local/bin/redis-server *:6000 [cluster](processInputBuffer(client*, bool, int)+0x174) [0x564315369414]
/usr/local/bin/redis-server *:6000 [cluster](processClients()+0xd9) [0x5643153695a9]
/usr/local/bin/redis-server *:6000 [cluster](+0x19aec2) [0x5643153a1ec2]
/usr/local/bin/redis-server *:6000 [cluster](beforeSleep(aeEventLoop*)+0x160) [0x56431534e6d0]
/usr/local/bin/redis-server *:6000 [cluster](aeProcessEvents+0x10b) [0x564315348eab]
/usr/local/bin/redis-server *:6000 [cluster](aeMain+0x47) [0x56431534f887]
/usr/local/bin/redis-server *:6000 [cluster](workerThreadMain(void*)+0x73) [0x56431540ff23]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7f820c9936db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f820c6bc88f]

------ INFO OUTPUT ------
# Server
redis_version:6.3.2
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:d352759e04d75ec2
redis_mode:cluster
os:Linux 4.15.0-96-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:7.3.0
process_id:11058
process_supervised:no
run_id:c51e6a438156c5d9b7c1c5a8c736789bc6d6413f
tcp_port:6000
server_time_usec:1681283248821382
uptime_in_seconds:68542
uptime_in_days:0
hz:250
configured_hz:250
lru_clock:3561648
executable:/usr/bin/keydb-server
config_file:/etc/keydb/keydb-6000.conf

# Clients
connected_clients:21432
cluster_connections:310
maxclients:40000
client_recent_max_input_buffer:262184
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
current_client_thread:1
thread_0_clients:10632
thread_1_clients:10808

# Memory
used_memory:29110554048
used_memory_human:27.11G
used_memory_rss:32960708608
used_memory_rss_human:30.70G
used_memory_peak:30144604896
used_memory_peak_human:28.07G
used_memory_peak_perc:96.57%
used_memory_overhead:5528078578
used_memory_startup:8060248
used_memory_dataset:23582475470
used_memory_dataset_perc:81.03%
allocator_allocated:29121224720
allocator_active:32949698560
allocator_resident:33602326528
total_system_memory:404357001216
total_system_memory_human:376.59G
used_memory_lua:105472
used_memory_lua_human:103.00K
used_memory_scripts:8040
used_memory_scripts_human:7.85K
number_of_cached_scripts:25
maxmemory:35000000000
maxmemory_human:32.60G
maxmemory_policy:noeviction
allocator_frag_ratio:1.13
allocator_frag_bytes:3828473840
allocator_rss_ratio:1.02
allocator_rss_bytes:652627968
rss_overhead_ratio:0.98
rss_overhead_bytes:-641617920
mem_fragmentation_ratio:1.13
mem_fragmentation_bytes:3840271256
mem_not_counted_for_evict:536870912
mem_replication_backlog:536870912
mem_clients_slaves:208360
mem_clients_normal:440022218
mem_aof_buffer:0
mem_allocator:jemalloc-5.2.1
active_defrag_running:13
lazyfree_pending_objects:0
lazyfreed_objects:6
storage_provider:none

# Persistence
loading: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:358831116
rdb_bgsave_in_progress:0
rdb_last_save_time:1681214706
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:173488
total_commands_processed:270461139
instantaneous_ops_per_sec:4485
total_net_input_bytes:57781899796
total_net_output_bytes:310014163991
instantaneous_input_kbps:701.29
instantaneous_output_kbps:4458.64
rejected_connections:0
sync_full:0
sync_partial_ok:8
sync_partial_err:0
expired_keys:59078451
expired_stale_perc:0.00
expired_time_cap_reached_count:42436
expire_cycle_cpu_milliseconds:0
evicted_keys:0
keyspace_hits:35669403
keyspace_misses:32188779
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:0
total_forks:0
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:127325563
active_defrag_misses:18115209786
active_defrag_key_hits:55526500
active_defrag_key_misses:2684676198
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:51
dump_payload_sanitizations:0
total_reads_processed:210449009
total_writes_processed:1295043744
instantaneous_lock_contention:2
avg_lock_contention:1.234375
storage_provider_read_hits:0
storage_provider_read_misses:0

# Replication
role:master
connected_slaves:8
slave0:ip=10.64.54.10,port=40012,state=online,offset=52019016970889,lag=0
slave1:ip=10.64.40.28,port=6001,state=online,offset=52019016656288,lag=1
slave2:ip=10.64.46.19,port=6005,state=online,offset=52019016656288,lag=1
slave3:ip=10.64.56.5,port=40010,state=online,offset=52019016656641,lag=1
slave4:ip=10.64.48.20,port=6006,state=online,offset=52019016891114,lag=0
slave5:ip=10.64.49.12,port=6008,state=online,offset=52019016691072,lag=0
slave6:ip=10.64.49.10,port=6007,state=online,offset=52019016773689,lag=0
slave7:ip=10.64.37.6,port=6009,state=online,offset=52019016891818,lag=0
master_failover_state:no-failover
master_replid:e1896072291a4348276a70c0df81229318eb0890
master_replid2:57a7934ae9708681637a8ae20f3bda3b853ba41c
master_repl_offset:52019017044857
second_repl_offset:51986981234902
repl_backlog_active:1
repl_backlog_size:536870912
repl_backlog_first_byte_offset:52018480173946
repl_backlog_histlen:536870912

# CPU
used_cpu_sys:8178.709064
used_cpu_user:27959.011523
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
server_threads:2
long_lock_waits:8739
used_cpu_sys_main_thread:3481.718818
used_cpu_user_main_thread:12334.450114

# Modules

# Commandstats
cmdstat_zcount:calls=2360,usec=9768,usec_per_call=4.14,rejected_calls=0,failed_calls=0
cmdstat_zcard:calls=645,usec=1464,usec_per_call=2.27,rejected_calls=0,failed_calls=0
cmdstat_readonly:calls=1462948,usec=478263,usec_per_call=0.33,rejected_calls=0,failed_calls=0
cmdstat_zscore:calls=2724,usec=16568,usec_per_call=6.08,rejected_calls=0,failed_calls=0
cmdstat_info:calls=11121,usec=858680,usec_per_call=77.21,rejected_calls=0,failed_calls=0
cmdstat_hincrby:calls=7,usec=36,usec_per_call=5.14,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=278,usec=79,usec_per_call=0.28,rejected_calls=0,failed_calls=0
cmdstat_llen:calls=42302,usec=115027,usec_per_call=2.72,rejected_calls=0,failed_calls=0
cmdstat_replconf:calls=511679,usec=206925,usec_per_call=0.40,rejected_calls=0,failed_calls=0
cmdstat_ttl:calls=993757,usec=1788455,usec_per_call=1.80,rejected_calls=0,failed_calls=0
cmdstat_exec:calls=984198,usec=8699809,usec_per_call=8.84,rejected_calls=0,failed_calls=0
cmdstat_lrange:calls=1249742,usec=7255512,usec_per_call=5.81,rejected_calls=0,failed_calls=0
cmdstat_pttl:calls=305004,usec=180014,usec_per_call=0.59,rejected_calls=0,failed_calls=0
cmdstat_hget:calls=160508,usec=611540,usec_per_call=3.81,rejected_calls=0,failed_calls=0
cmdstat_restore:calls=258280,usec=8149194,usec_per_call=31.55,rejected_calls=0,failed_calls=0
cmdstat_decrby:calls=29417,usec=107312,usec_per_call=3.65,rejected_calls=0,failed_calls=0
cmdstat_zremrangebyscore:calls=372696,usec=2451875,usec_per_call=6.58,rejected_calls=0,failed_calls=0
cmdstat_psync:calls=8,usec=404,usec_per_call=50.50,rejected_calls=0,failed_calls=0
cmdstat_hset:calls=25512482,usec=74827664,usec_per_call=2.93,rejected_calls=0,failed_calls=0
cmdstat_decr:calls=930,usec=3283,usec_per_call=3.53,rejected_calls=0,failed_calls=0
cmdstat_zrange:calls=10204,usec=54196,usec_per_call=5.31,rejected_calls=0,failed_calls=0
cmdstat_zremrangebyrank:calls=4489,usec=816241,usec_per_call=181.83,rejected_calls=0,failed_calls=0
cmdstat_expire:calls=48811850,usec=72422029,usec_per_call=1.48,rejected_calls=0,failed_calls=0
cmdstat_get:calls=40120834,usec=52171580,usec_per_call=1.30,rejected_calls=0,failed_calls=0
cmdstat_zrank:calls=9,usec=43,usec_per_call=4.78,rejected_calls=0,failed_calls=0
cmdstat_zrangebyscore:calls=10632,usec=161271,usec_per_call=15.17,rejected_calls=0,failed_calls=0
cmdstat_set:calls=41226545,usec=295345291,usec_per_call=7.16,rejected_calls=1,failed_calls=0
cmdstat_replping:calls=1,usec=1,usec_per_call=1.00,rejected_calls=0,failed_calls=0
cmdstat_select:calls=1,usec=1,usec_per_call=1.00,rejected_calls=0,failed_calls=0
cmdstat_command:calls=1,usec=541,usec_per_call=541.00,rejected_calls=0,failed_calls=0
cmdstat_dump:calls=305004,usec=7600341,usec_per_call=24.92,rejected_calls=0,failed_calls=0
cmdstat_sismember:calls=166792,usec=583965,usec_per_call=3.50,rejected_calls=0,failed_calls=0
cmdstat_zadd:calls=1010139,usec=18087074,usec_per_call=17.91,rejected_calls=0,failed_calls=0
cmdstat_zrevrange:calls=81,usec=1447,usec_per_call=17.86,rejected_calls=0,failed_calls=0
cmdstat_scan:calls=512,usec=105565403,usec_per_call=206182.42,rejected_calls=0,failed_calls=0
cmdstat_rename:calls=360592,usec=7957411,usec_per_call=22.07,rejected_calls=0,failed_calls=0
cmdstat_incr:calls=12871541,usec=69295081,usec_per_call=5.38,rejected_calls=0,failed_calls=0
cmdstat_slowlog:calls=9136,usec=9074,usec_per_call=0.99,rejected_calls=0,failed_calls=0
cmdstat_hmget:calls=22873262,usec=258242585,usec_per_call=11.29,rejected_calls=0,failed_calls=0
cmdstat_exists:calls=1432550,usec=3524752,usec_per_call=2.46,rejected_calls=0,failed_calls=0
cmdstat_config:calls=4570,usec=279949,usec_per_call=61.26,rejected_calls=0,failed_calls=0
cmdstat_zrem:calls=7,usec=51,usec_per_call=7.29,rejected_calls=0,failed_calls=0
cmdstat_hdel:calls=928458,usec=2145522,usec_per_call=2.31,rejected_calls=0,failed_calls=0
cmdstat_sadd:calls=59338,usec=281033,usec_per_call=4.74,rejected_calls=0,failed_calls=0
cmdstat_hgetall:calls=181760,usec=1809973,usec_per_call=9.96,rejected_calls=0,failed_calls=0
cmdstat_latency:calls=4568,usec=10172,usec_per_call=2.23,rejected_calls=0,failed_calls=0
cmdstat_unlink:calls=12,usec=76,usec_per_call=6.33,rejected_calls=0,failed_calls=0
cmdstat_incrby:calls=15811554,usec=31235214,usec_per_call=1.98,rejected_calls=0,failed_calls=0
cmdstat_hmset:calls=10696981,usec=125073292,usec_per_call=11.69,rejected_calls=0,failed_calls=0
cmdstat_eval:calls=26059030,usec=576469871,usec_per_call=22.12,rejected_calls=0,failed_calls=0
cmdstat_srandmember:calls=12,usec=74,usec_per_call=6.17,rejected_calls=0,failed_calls=0
cmdstat_del:calls=9472829,usec=40132610,usec_per_call=4.24,rejected_calls=0,failed_calls=0
cmdstat_multi:calls=984198,usec=96909,usec_per_call=0.10,rejected_calls=0,failed_calls=0
cmdstat_rpush:calls=1242706,usec=15383440,usec_per_call=12.38,rejected_calls=0,failed_calls=0
cmdstat_setex:calls=3647316,usec=29379207,usec_per_call=8.06,rejected_calls=0,failed_calls=0
cmdstat_cluster:calls=252539,usec=35966585,usec_per_call=142.42,rejected_calls=49,failed_calls=0

# Errorstats
errorstat_ERR:count=1
errorstat_LOADING:count=49
errorstat_MOVED:count=1

# Cluster
cluster_enabled:1

# Keyspace
db0:keys=69118600,expires=68497453,avg_ttl=1993500801,cached_keys=69118600

# KeyDB
mvcc_depth:1

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

Aditional information

Ubuntu 18.04.4, Linux 4.15.0-96-generic #97-Ubuntu SMP Wed Apr 1 03:25:46 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux.

The server has crashed and gracefully restarted.

Probably somehow related to problem depicted in #250

[msotheeswaran-sc]

hi @r00t3g can you provide more details about your configuration?

[r00t3g]

Hi @msotheeswaran .

We are running KeyDB as a replacement to one of our production Redis Cluster shards. Basically we took the same config file, added some KeyDB-related settings (server-threads, etc) and basically switched all the nodes within one cluster shard to KeyDB.

The reported behavior occurred only on the primary (master) node, did not occur on secondaries (slaves).

The rest of the cluster remained on Redis 5.x.

After downgrading to 6.2 the problem stopped occurring and everything runs smooth and stable.

Probably, exactly 27cb5db for v. 6.3.2 might have caused the problem.

[r00t3g]

Oh, and please don't be confused with /usr/local/bin/redis-server binary path - it's KeyDB, we just had to rename the binary as our monitoring currently uses Prometheus Named Process Group exporter which monitors redis-server, and, since it is a test-drive, we have just kept the process name.