Skip to content

[CRASH] 'ckeysExpired == db->expireSize()' is not true, on Active Replication #428

@solracsf

Description

@solracsf

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.

=== KEYDB BUG REPORT START: Cut & paste starting from here ===
4111939:4129518:S 18 May 2022 15:21:08.202 # === ASSERTION FAILED ===
4111939:4129518:S 18 May 2022 15:21:08.202 # ==> rdb.cpp:1376 'ckeysExpired == db->expireSize()' is not true

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

Backtrace:
/usr/bin/keydb-server 127.0.0.1:6379(rdbSaveRio(_rio*, redisDbPersistentDataSnapshot const**, int*, int, rdbSaveInfo*)+0x51d) [0x5602b3331bdd]
/usr/bin/keydb-server 127.0.0.1:6379(rdbSaveFile(char*, redisDbPersistentDataSnapshot const**, rdbSaveInfo*)+0xea) [0x5602b3331cfa]
/usr/bin/keydb-server 127.0.0.1:6379(rdbSave(redisDbPersistentDataSnapshot const**, rdbSaveInfo*)+0x69) [0x5602b3332029]
/usr/bin/keydb-server 127.0.0.1:6379(rdbSaveThread(void*)+0x30f) [0x5602b33378ef]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8609) [0x7f1f460ce609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43) [0x7f1f45ff1133]

------ INFO OUTPUT ------
# Server
redis_version:6.3.0
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:bc455d014a017397
redis_mode:standalone
os:Linux 5.4.0-109-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:9.3.0
process_id:4111939
process_supervised:systemd
run_id:ad877fcb161cb43c31ce8d9f81734a7e3228d576
tcp_port:6379
server_time_usec:1652880068198069
uptime_in_seconds:602
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:8712900
executable:/usr/bin/keydb-server
config_file:/etc/keydb/keydb.conf

# Clients
connected_clients:215
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:360
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
current_client_thread:1735743595
thread_0_clients:108
thread_1_clients:108

# Memory
used_memory:38511784
used_memory_human:36.73M
used_memory_rss:31891456
used_memory_rss_human:30.41M
used_memory_peak:38569200
used_memory_peak_human:36.78M
used_memory_peak_perc:99.85%
used_memory_overhead:16214832
used_memory_startup:10419760
used_memory_dataset:22296952
used_memory_dataset_perc:79.37%
allocator_allocated:18851992
allocator_active:21073920
allocator_resident:27336704
total_system_memory:8144506880
total_system_memory_human:7.59G
used_memory_lua:37888
used_memory_lua_human:37.00K
used_memory_scripts:0
used_memory_scripts_human:0B
number_of_cached_scripts:0
maxmemory:1073741824
maxmemory_human:1.00G
maxmemory_policy:allkeys-lru
allocator_frag_ratio:1.12
allocator_frag_bytes:2221928
allocator_rss_ratio:1.30
allocator_rss_bytes:6262784
rss_overhead_ratio:1.17
rss_overhead_bytes:4554752
mem_fragmentation_ratio:1.79
mem_fragmentation_bytes:14078128
mem_not_counted_for_evict:1048576
mem_replication_backlog:1048576
mem_clients_slaves:20512
mem_clients_normal:4223992
mem_aof_buffer:0
mem_allocator:jemalloc-5.2.1
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0
storage_provider:none

# Persistence
loading:0
current_cow_size:34770944
current_cow_size_age:600
current_fork_perc:0.00
current_save_keys_processed:1
current_save_keys_total:0
rdb_changes_since_last_save:4634
rdb_bgsave_in_progress:1
rdb_last_save_time:1652879467
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_current_bgsave_time_sec:0
rdb_last_cow_size:34832384
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:628
total_commands_processed:32723
instantaneous_ops_per_sec:742
total_net_input_bytes:4073064
total_net_output_bytes:4519032
instantaneous_input_kbps:91.21
instantaneous_output_kbps:262.27
rejected_connections:0
sync_full:2
sync_partial_ok:0
sync_partial_err:1
expired_keys:334
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
keyspace_hits:10156
keyspace_misses:3297
pubsub_channels:11
pubsub_patterns: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
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:26570
total_writes_processed:32693
instantaneous_lock_contention:0
avg_lock_contention:0.203125
storage_provider_read_hits:0
storage_provider_read_misses:0

# Replication
role:active-replica
master_global_link_status:down
connected_masters:0
master_host:10.1.0.3
master_port:6379
master_link_status:down
master_last_io_seconds_ago:-1
master_sync_in_progress:0
slave_read_repl_offset:2168278
slave_repl_offset:2168278
master_link_down_since_seconds:1
slave_priority:100
slave_read_only:0
replica_announced:1
connected_slaves:1
slave0:ip=10.1.0.3,port=6379,state=wait_bgsave,offset=0,lag=0
master_failover_state:no-failover
master_replid:5ee7555c20391d1be81921a4fc235548d0766dff
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:1799392
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:750817
repl_backlog_histlen:1048576

# CPU
used_cpu_sys:5.855103
used_cpu_user:8.091830
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
server_threads:2
long_lock_waits:2
used_cpu_sys_main_thread:0.000000
used_cpu_user_main_thread:0.012034

# Modules

# Commandstats
cmdstat_psync:calls=2,usec=29419,usec_per_call=14709.50,rejected_calls=0,failed_calls=0
cmdstat_set:calls=2074,usec=20492,usec_per_call=9.88,rejected_calls=0,failed_calls=0
cmdstat_watch:calls=89,usec=238,usec_per_call=2.67,rejected_calls=0,failed_calls=0
cmdstat_echo:calls=1844,usec=5421,usec_per_call=2.94,rejected_calls=0,failed_calls=0
cmdstat_pexpireat:calls=219,usec=1567,usec_per_call=7.16,rejected_calls=0,failed_calls=0
cmdstat_multi:calls=193,usec=141,usec_per_call=0.73,rejected_calls=0,failed_calls=0
cmdstat_expire:calls=95,usec=533,usec_per_call=5.61,rejected_calls=0,failed_calls=0
cmdstat_replping:calls=2,usec=3,usec_per_call=1.50,rejected_calls=0,failed_calls=0
cmdstat_incrby:calls=263,usec=2013,usec_per_call=7.65,rejected_calls=0,failed_calls=0
cmdstat_decrby:calls=62,usec=511,usec_per_call=8.24,rejected_calls=0,failed_calls=0
cmdstat_get:calls=12515,usec=100004,usec_per_call=7.99,rejected_calls=0,failed_calls=0
cmdstat_unwatch:calls=22,usec=67,usec_per_call=3.05,rejected_calls=0,failed_calls=0
cmdstat_KEYDB.MVCCRESTORE:calls=576,usec=1632,usec_per_call=2.83,rejected_calls=0,failed_calls=0
cmdstat_exists:calls=1697,usec=5775,usec_per_call=3.40,rejected_calls=0,failed_calls=0
cmdstat_select:calls=2465,usec=5350,usec_per_call=2.17,rejected_calls=0,failed_calls=0
cmdstat_rreplay:calls=7787,usec=105476,usec_per_call=13.55,rejected_calls=0,failed_calls=0
cmdstat_setex:calls=1137,usec=17234,usec_per_call=15.16,rejected_calls=0,failed_calls=0
cmdstat_del:calls=169,usec=1209,usec_per_call=7.15,rejected_calls=0,failed_calls=0
cmdstat_subscribe:calls=187,usec=920,usec_per_call=4.92,rejected_calls=0,failed_calls=0
cmdstat_exec:calls=193,usec=2845,usec_per_call=14.74,rejected_calls=0,failed_calls=0
cmdstat_replconf:calls=601,usec=1249,usec_per_call=2.08,rejected_calls=0,failed_calls=0
cmdstat_publish:calls=472,usec=10652,usec_per_call=22.57,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=59,usec=43,usec_per_call=0.73,rejected_calls=0,failed_calls=0

# Errorstats

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=71,expires=65,avg_ttl=8390370178780633088,cached_keys=71
db1:keys=14,expires=14,avg_ttl=7625909362398592000,cached_keys=14
db2:keys=241,expires=180,avg_ttl=43798964773871976,cached_keys=241
db3:keys=11,expires=0,avg_ttl=0,cached_keys=11
db4:keys=56,expires=51,avg_ttl=3439822868195400192,cached_keys=56
db5:keys=19,expires=0,avg_ttl=0,cached_keys=19
db6:keys=93,expires=73,avg_ttl=12277952439748620,cached_keys=93
db7:keys=19,expires=0,avg_ttl=0,cached_keys=19
db8:keys=634,expires=573,avg_ttl=20705572669190216,cached_keys=634
db9:keys=69,expires=61,avg_ttl=1402508465148768512,cached_keys=69
db10:keys=19,expires=15,avg_ttl=171040,cached_keys=19
db11:keys=58,expires=38,avg_ttl=137730,cached_keys=58
db12:keys=40,expires=36,avg_ttl=508864,cached_keys=40
db13:keys=24,expires=2,avg_ttl=355779,cached_keys=24
db14:keys=4,expires=0,avg_ttl=0,cached_keys=4
db15:keys=24,expires=0,avg_ttl=0,cached_keys=24
db16:keys=21,expires=17,avg_ttl=3430029413725811712,cached_keys=21
db17:keys=25,expires=19,avg_ttl=3515942792136043520,cached_keys=25
db18:keys=7,expires=7,avg_ttl=723099224529815808,cached_keys=7
db19:keys=70,expires=59,avg_ttl=3968513367523315712,cached_keys=70
db20:keys=93,expires=85,avg_ttl=824537412792734336,cached_keys=93
db21:keys=25,expires=21,avg_ttl=6751038335294198784,cached_keys=25
db22:keys=20,expires=6,avg_ttl=292394,cached_keys=20
db23:keys=15,expires=3,avg_ttl=202586,cached_keys=15
db24:keys=426,expires=381,avg_ttl=2995350098082836,cached_keys=426
db25:keys=26,expires=20,avg_ttl=501913,cached_keys=26
db26:keys=28,expires=23,avg_ttl=2430460415709187584,cached_keys=28
db28:keys=15,expires=0,avg_ttl=0,cached_keys=15
db29:keys=27,expires=5,avg_ttl=180590,cached_keys=27
db30:keys=8,expires=8,avg_ttl=6959879998927706112,cached_keys=8
db31:keys=28,expires=0,avg_ttl=0,cached_keys=28
db32:keys=152,expires=29,avg_ttl=48829607915297352,cached_keys=152
db33:keys=15,expires=3,avg_ttl=62899,cached_keys=15
db34:keys=23,expires=0,avg_ttl=0,cached_keys=23
db35:keys=21,expires=0,avg_ttl=0,cached_keys=21
db36:keys=19,expires=0,avg_ttl=0,cached_keys=19
db37:keys=15,expires=0,avg_ttl=0,cached_keys=15
db38:keys=5,expires=1,avg_ttl=211904,cached_keys=5
db39:keys=24,expires=4,avg_ttl=67102,cached_keys=24

# KeyDB
mvcc_depth:2

Aditional information

  1. Ubuntu 20.04
  2. KeyDB v6.3.0

Latest log lines before crash were:

4111939:4111948:S 18 May 2022 15:21:07.860 # Connection with replica client id #7 lost.
4111939:4111948:S 18 May 2022 15:21:07.860 # Connection with master lost.
4111939:4111948:S 18 May 2022 15:21:07.860 * Caching the disconnected master state.
4111939:4111949:S 18 May 2022 15:21:08.174 * Replica 10.1.0.3:6379 asks for synchronization
4111939:4111949:S 18 May 2022 15:21:08.174 * Unable to partial resync with replica 10.1.0.3:6379 for lack of backlog (Replica request was: 0).
4111939:4111949:S 18 May 2022 15:21:08.174 * Starting BGSAVE for SYNC with target: disk
4111939:4111949:S 18 May 2022 15:21:08.189 * Background saving started

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions