Open
Description
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