KeyDB
KeyDB copied to clipboard
Snapchat
[CRASH] assertion failed during restart (db.cpp:2908 'm_fTrackingChanges >= 0' is not true)
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.
449746:449758:S 10 Jan 2023 18:25:28.293 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:25:31.096 * 10000 changes in 60 seconds. Saving...
449746:449757:S 10 Jan 2023 18:25:31.096 * Background saving started
449746:449757:S 10 Jan 2023 18:25:33.599 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:25:34.099 # Accepting client connection: accept: Too many open files
449746:449758:S 10 Jan 2023 18:25:34.099 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:26:34.966 * Connecting to MASTER 10.70.32.242:6379
449746:449757:S 10 Jan 2023 18:26:35.107 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:26:56.090 * 10000 changes in 60 seconds. Saving...
449746:449757:S 10 Jan 2023 18:26:56.090 * Background saving started
449746:449757:S 10 Jan 2023 18:27:08.103 # Background saving error
449746:449757:S 10 Jan 2023 18:27:14.110 # Background saving error
449746:449757:S 10 Jan 2023 18:27:24.221 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:27:24.721 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:27:26.023 * 10000 changes in 60 seconds. Saving...
449746:449757:S 10 Jan 2023 18:27:26.023 * Background saving started
449746:449757:S 10 Jan 2023 18:27:26.123 # Background saving error
449746:449757:S 10 Jan 2023 18:27:34.532 # Accepting client connection: accept: Too many open files
449746:449758:S 10 Jan 2023 18:27:34.533 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:27:55.055 * Connecting to MASTER 10.70.32.242:6379
449746:449757:S 10 Jan 2023 18:27:56.056 * 10000 changes in 60 seconds. Saving...
449746:449757:S 10 Jan 2023 18:27:56.057 * Background saving started
449746:449757:S 10 Jan 2023 18:27:56.657 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:27:57.358 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:28:17.280 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:28:34.484 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:28:57.123 * Connecting to MASTER 10.70.32.242:6379
449746:449757:S 10 Jan 2023 18:29:01.028 * 10000 changes in 60 seconds. Saving...
449746:449757:S 10 Jan 2023 18:29:01.028 * Background saving started
449746:449757:S 10 Jan 2023 18:29:19.148 # Background saving error
449746:449757:S 10 Jan 2023 18:29:31.489 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:29:36.690 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:29:56.992 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:30:00.292 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:30:01.194 # Background saving error
449746:449757:S 10 Jan 2023 18:30:01.194 * Connecting to MASTER 10.70.32.242:6379
449746:449757:S 10 Jan 2023 18:30:11.304 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:30:18.012 * 10000 changes in 60 seconds. Saving...
449746:449757:S 10 Jan 2023 18:30:18.012 * Background saving started
449746:signal-handler (1673371820) Received SIGTERM scheduling shutdown...
449746:449758:S 10 Jan 2023 18:30:20.426 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:30:20.426 # Accepting client connection: accept: Too many open files
449746:449758:S 10 Jan 2023 18:30:20.652 # Accepting client connection: accept: Too many open files
449746:449757:S 10 Jan 2023 18:30:20.817 # Background saving error
449746:449757:S 10 Jan 2023 18:30:20.817 # SYNC failed. BGSAVE child returned an error
449746:449758:S 10 Jan 2023 18:30:20.817 # Connection with replica 10.70.32.242:6379 lost.
449746:449757:S 10 Jan 2023 18:30:20.920 * Replica 10.70.32.242:6379 asks for synchronization
449746:449757:S 10 Jan 2023 18:30:20.921 * Full resync requested by replica 10.70.32.242:6379
449746:449757:S 10 Jan 2023 18:30:20.921 * Starting BGSAVE for SYNC with target: disk
449746:449757:S 10 Jan 2023 18:30:20.921 * Background saving started
449746:2244502:S 10 Jan 2023 18:30:20.976 * DB saved on disk
449746:2244502:S 10 Jan 2023 18:30:20.977 * RDB: 18 MB of memory used by copy-on-write
449746:449757:S 10 Jan 2023 18:30:21.019 * Background saving terminated with success
449746:449757:S 10 Jan 2023 18:30:21.040 * Synchronization with replica 10.70.32.242:6379 succeeded
449746:449757:S 10 Jan 2023 18:30:21.320 # Connection with replica client id #7687818 lost.
449746:449757:S 10 Jan 2023 18:30:21.574 * Replica 10.70.32.242:6379 asks for synchronization
449746:449757:S 10 Jan 2023 18:30:21.574 * Unable to partial resync with replica 10.70.32.242:6379 for lack of backlog (Replica request was: 122354139062).
449746:449757:S 10 Jan 2023 18:30:21.574 * Starting BGSAVE for SYNC with target: disk
449746:449757:S 10 Jan 2023 18:30:21.574 * Background saving started
449746:2244506:S 10 Jan 2023 18:30:21.627 * DB saved on disk
449746:2244506:S 10 Jan 2023 18:30:21.628 * RDB: 18 MB of memory used by copy-on-write
449746:449757:S 10 Jan 2023 18:30:21.727 * Background saving terminated with success
449746:449757:S 10 Jan 2023 18:30:21.733 * Synchronization with replica 10.70.32.242:6379 succeeded
449746:449757:S 10 Jan 2023 18:31:02.471 # Timeout connecting to the MASTER...
449746:449757:S 10 Jan 2023 18:31:03.476 * Connecting to MASTER 10.70.32.242:6379
449746:449757:S 10 Jan 2023 18:31:03.476 * MASTER <-> REPLICA sync started
449746:449757:S 10 Jan 2023 18:31:03.477 * Non blocking connect for SYNC fired the event.
449746:449757:S 10 Jan 2023 18:31:03.477 * Master replied to PING, replication can continue...
449746:449757:S 10 Jan 2023 18:31:03.478 * Trying a partial resynchronization (request 9868c0da0bd965cf8506c53192c56e49e4355460:133382274204).
449746:449757:S 10 Jan 2023 18:31:03.480 * Full resync from master: 9868c0da0bd965cf8506c53192c56e49e4355460:165719130277
449746:449757:S 10 Jan 2023 18:31:03.480 * Discarding previously cached master state.
449746:449757:S 10 Jan 2023 18:31:03.687 * MASTER <-> REPLICA sync: receiving 5732587 bytes from master to disk
449746:449757:S 10 Jan 2023 18:31:03.736 * MASTER <-> REPLICA sync: Loading DB in memory
=== KEYDB BUG REPORT START: Cut & paste starting from here ===
449746:449757:S 10 Jan 2023 18:31:03.753 # === ASSERTION FAILED ===
449746:449757:S 10 Jan 2023 18:31:03.753 # ==> db.cpp:2908 'm_fTrackingChanges >= 0' is not true
------ STACK TRACE ------
Backtrace:
/usr/bin/keydb-server *:6379(redisDbPersistentData::processChanges(bool)+0x106) [0x55b49fccae26]
/usr/bin/keydb-server *:6379(rdbLoadRio(_rio*, int, rdbSaveInfo*)+0x316) [0x55b49fd50b76]
/usr/bin/keydb-server *:6379(rdbLoadFile(char const*, rdbSaveInfo*, int)+0x67) [0x55b49fd533c7]
/usr/bin/keydb-server *:6379(readSyncBulkPayloadRdb(connection*, redisMaster*, rdbSaveInfo&, int&)+0x33e) [0x55b49fce97ee]
/usr/bin/keydb-server *:6379(readSyncBulkPayload(connection*)+0xbc) [0x55b49fcead9c]
/usr/bin/keydb-server *:6379(connSocketEventHandler(aeEventLoop*, int, void*, int)+0x110) [0x55b49fd3b210]
/usr/bin/keydb-server *:6379(ProcessEventCore+0x12d) [0x55b49fc5cffd]
/usr/bin/keydb-server *:6379(aeProcessEvents+0x235) [0x55b49fc5eb35]
/usr/bin/keydb-server *:6379(aeMain+0x47) [0x55b49fc68457]
/usr/bin/keydb-server *:6379(workerThreadMain(void*)+0x73) [0x55b49fd2d763]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7f5d960226db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f5d95d4b61f]
------ INFO OUTPUT ------
# Server
redis_version:6.3.1
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:3fe315c8f17a49e
redis_mode:standalone
os:Linux 5.15.0-39-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:7.3.0
process_id:449746
process_supervised:no
run_id:c11c6f348a3fc06a50ebf92dd004c6077aacc355
tcp_port:6379
server_time_usec:1673371863754269
uptime_in_seconds:4306325
uptime_in_days:49
hz:10
configured_hz:10
lru_clock:12427479
executable:/usr/bin/keydb-server
config_file:/etc/keydb/keydb.conf
# Clients
connected_clients:19
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:32
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
current_client_thread:0
thread_0_clients:12
thread_1_clients:8
# Memory
used_memory:8275784
used_memory_human:7.89M
used_memory_rss:25993216
used_memory_rss_human:24.79M
used_memory_peak:19698776
used_memory_peak_human:18.79M
used_memory_peak_perc:42.01%
used_memory_overhead:5082696
used_memory_startup:2092384
used_memory_dataset:3193088
used_memory_dataset_perc:51.64%
allocator_allocated:9569320
allocator_active:12914688
allocator_resident:22278144
total_system_memory:270354784256
total_system_memory_human:251.79G
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:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.35
allocator_frag_bytes:3345368
allocator_rss_ratio:1.73
allocator_rss_bytes:9363456
rss_overhead_ratio:1.17
rss_overhead_bytes:3715072
mem_fragmentation_ratio:3.14
mem_fragmentation_bytes:17719272
mem_not_counted_for_evict:1048576
mem_replication_backlog:1048576
mem_clients_slaves:20512
mem_clients_normal:389280
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:1
current_cow_size:18595840
current_cow_size_age:42
current_fork_perc:0.00
current_save_keys_processed:1
current_save_keys_total:0
rdb_changes_since_last_save:606
rdb_bgsave_in_progress:0
rdb_last_save_time:1673371821
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:19460096
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
loading_start_time:1673371863
loading_total_bytes:5732587
loading_rdb_used_mem:0
loading_loaded_bytes:0
loading_loaded_perc:0.00
loading_eta_seconds:1
# Stats
total_connections_received:7687854
total_commands_processed:365051884
instantaneous_ops_per_sec:0
total_net_input_bytes:42703256002
total_net_output_bytes:89465415839
instantaneous_input_kbps:0.03
instantaneous_output_kbps:0.00
rejected_connections:0
sync_full:3
sync_partial_ok:1
sync_partial_err:2
expired_keys:911430
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
keyspace_hits:94585327
keyspace_misses:786787
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: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:7
dump_payload_sanitizations:0
total_reads_processed:326375834
total_writes_processed:651809062
instantaneous_lock_contention:1
avg_lock_contention:0.000000
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.70.32.242
master_port:6379
master_link_status:down
master_last_io_seconds_ago:-1
master_sync_in_progress:1
slave_read_repl_offset:1
slave_repl_offset:1
master_sync_total_bytes:5732587
master_sync_read_bytes:5732587
master_sync_left_bytes:0
master_sync_perc:100.00
master_sync_last_io_seconds_ago:0
master_link_down_since_seconds:3726491
slave_priority:100
slave_read_only:0
replica_announced:1
connected_slaves:1
slave0:ip=10.70.32.242,port=6379,state=online,offset=153590571135,lag=1
master_failover_state:no-failover
master_replid:cee9e7c3158fd56daecad9ff6a07f2b2a1d68bb0
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:153590571135
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:153589522560
repl_backlog_histlen:1048576
# CPU
used_cpu_sys:723308.804973
used_cpu_user:3065456.523140
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
server_threads:2
long_lock_waits:145810
used_cpu_sys_main_thread:306961.591955
used_cpu_user_main_thread:1473347.976529
# Modules
# Commandstats
cmdstat_replping:calls=0,usec=0,usec_per_call=0.00,rejected_calls=7,failed_calls=0
cmdstat_replconf:calls=574399,usec=1002486,usec_per_call=1.75,rejected_calls=0,failed_calls=0
cmdstat_pexpireat:calls=9480984,usec=66384821,usec_per_call=7.00,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=64593219,usec=71971399,usec_per_call=1.11,rejected_calls=0,failed_calls=0
cmdstat_psync:calls=4,usec=1889,usec_per_call=472.25,rejected_calls=0,failed_calls=0
cmdstat_expire:calls=63932130,usec=381967276,usec_per_call=5.97,rejected_calls=0,failed_calls=0
cmdstat_del:calls=508042,usec=3770417,usec_per_call=7.42,rejected_calls=0,failed_calls=0
cmdstat_monitor:calls=1,usec=2,usec_per_call=2.00,rejected_calls=0,failed_calls=0
cmdstat_hmset:calls=73413114,usec=749517762,usec_per_call=10.21,rejected_calls=0,failed_calls=0
cmdstat_rreplay:calls=57176008,usec=2324139433,usec_per_call=40.65,rejected_calls=0,failed_calls=0
cmdstat_hgetall:calls=63817286,usec=747900025,usec_per_call=11.72,rejected_calls=0,failed_calls=0
cmdstat_auth:calls=1869,usec=10874,usec_per_call=5.82,rejected_calls=0,failed_calls=0
cmdstat_get:calls=31554828,usec=166095158,usec_per_call=5.26,rejected_calls=0,failed_calls=0
# Errorstats
errorstat_NOAUTH:count=7
# Cluster
cluster_enabled:0
# Keyspace
db0:keys=13214,expires=13213,avg_ttl=6369152,cached_keys=13214
# KeyDB
mvcc_depth:0
------ CLIENT LIST OUTPUT ------
id=7686933 addr=127.0.0.1:57634 laddr=127.0.0.1:6379 fd=64894 name= age=60 idle=60 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686935 addr=127.0.0.1:57638 laddr=127.0.0.1:6379 fd=65187 name= age=52 idle=52 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686924 addr=127.0.0.1:57620 laddr=127.0.0.1:6379 fd=65281 name= age=63 idle=63 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686928 addr=127.0.0.1:56572 laddr=127.0.0.1:6379 fd=65215 name= age=62 idle=62 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686931 addr=127.0.0.1:57628 laddr=127.0.0.1:6379 fd=65484 name= age=62 idle=62 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686939 addr=127.0.0.1:57656 laddr=127.0.0.1:6379 fd=65307 name= age=45 idle=45 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686932 addr=127.0.0.1:56576 laddr=127.0.0.1:6379 fd=64951 name= age=61 idle=61 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686940 addr=127.0.0.1:57658 laddr=127.0.0.1:6379 fd=65461 name= age=45 idle=45 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686941 addr=127.0.0.1:56380 laddr=127.0.0.1:6379 fd=65275 name= age=44 idle=44 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686934 addr=127.0.0.1:56592 laddr=127.0.0.1:6379 fd=65411 name= age=52 idle=52 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686927 addr=127.0.0.1:57624 laddr=127.0.0.1:6379 fd=65365 name= age=63 idle=63 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686930 addr=127.0.0.1:57626 laddr=127.0.0.1:6379 fd=65513 name= age=62 idle=62 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686936 addr=127.0.0.1:57642 laddr=127.0.0.1:6379 fd=65494 name= age=46 idle=46 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686937 addr=127.0.0.1:57646 laddr=127.0.0.1:6379 fd=65286 name= age=46 idle=46 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686938 addr=127.0.0.1:57652 laddr=127.0.0.1:6379 fd=65526 name= age=45 idle=45 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686923 addr=127.0.0.1:57616 laddr=127.0.0.1:6379 fd=65534 name= age=63 idle=63 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7687822 addr=10.70.32.242:44136 laddr=10.70.32.243:6379 fd=0 name= age=42 idle=1 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20512 events=r cmd=replconf user=default redir=-1
id=7686926 addr=127.0.0.1:56454 laddr=127.0.0.1:6379 fd=65399 name= age=63 idle=63 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=7686929 addr=127.0.0.1:56544 laddr=127.0.0.1:6379 fd=65031 name= age=62 idle=62 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=4 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20488 events=r cmd=NULL user=default redir=-1
id=79 addr=127.0.0.1:34826 laddr=127.0.0.1:6379 fd=86 name= age=4306281 idle=2 flags=O db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20496 events=r cmd=monitor user=default redir=-1
------ MODULES INFO OUTPUT ------
------ FAST MEMORY TEST ------
449746:449757:S 10 Jan 2023 18:31:03.755 # main thread terminated
449746:449757:S 10 Jan 2023 18:31:03.755 # Bio thread for job type #0 terminated
449746:449757:S 10 Jan 2023 18:31:03.755 # Bio thread for job type #1 terminated
449746:449757:S 10 Jan 2023 18:31:03.755 # Bio thread for job type #2 terminated
Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.
=== KEYDB BUG REPORT END. Make sure to include from START to END. ===
Please report the crash by opening an issue on github:
https://github.com/JohnSully/KeyDB/issues
Suspect RAM error? Use keydb-server --test-memory to verify it.
2244624:2244624:C 10 Jan 2023 18:31:04.327 * 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.
2244625:2244624:C 10 Jan 2023 18:31:04.328 # oO0OoO0OoO0Oo KeyDB is starting oO0OoO0OoO0Oo
2244625:2244624:C 10 Jan 2023 18:31:04.328 # KeyDB version=6.3.1, bits=64, commit=00000000, modified=0, pid=2244625, just started
2244625:2244624:C 10 Jan 2023 18:31:04.328 # Configuration loaded
2244625:2244624:S 10 Jan 2023 18:31:04.329 * monotonic clock: POSIX clock_gettime
_
_-(+)-_
_-- / \ --_
_-- / \ --_ KeyDB 6.3.1 (00000000/0) 64 bit
__-- / \ --__
(+) _ / \ _ (+) Running in standalone mode
| -- / \ -- | Port: 6379
| /--_ _ _--\ | PID: 2244625
| / -(+)- \ |
| / | \ | https://docs.keydb.dev
| / | \ |
| / | \ |
(+)_ -- -- -- | -- -- -- _(+)
--_ | _--
--_ | _--
-(+)-
2244625:2244624:S 10 Jan 2023 18:31:04.335 # Server initialized
2244625:2244624:S 10 Jan 2023 18:31:04.335 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. 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.
2244625:2244624:S 10 Jan 2023 18:31:04.336 * Loading RDB produced by version 6.3.1
2244625:2244624:S 10 Jan 2023 18:31:04.336 * RDB age 43 seconds
2244625:2244624:S 10 Jan 2023 18:31:04.336 * RDB memory usage when created 9.63 Mb
2244625:2244624:S 10 Jan 2023 18:31:04.374 # Done loading RDB, keys loaded: 0, keys expired: 0.
2244625:2244624:S 10 Jan 2023 18:31:04.374 * DB loaded from disk: 0.039 seconds
2244625:2244624:S 10 Jan 2023 18:31:04.374 * RDB contains information on 1 masters
2244625:2244624:S 10 Jan 2023 18:31:04.374 * Cached master recovered from RDB for 10.70.32.242:6379
2244625:2244639:S 10 Jan 2023 18:31:04.375 * Thread 0 alive.
2244625:2244640:S 10 Jan 2023 18:31:04.375 * Thread 1 alive.
2244625:2244639:S 10 Jan 2023 18:31:04.375 * Connecting to MASTER 10.70.32.242:6379
2244625:2244639:S 10 Jan 2023 18:31:04.376 * MASTER <-> REPLICA sync started
2244625:2244639:S 10 Jan 2023 18:31:04.376 * Non blocking connect for SYNC fired the event.
2244625:2244639:S 10 Jan 2023 18:31:04.377 * Master replied to PING, replication can continue...
2244625:2244639:S 10 Jan 2023 18:31:04.377 * Trying a partial resynchronization (request 9868c0da0bd965cf8506c53192c56e49e4355460:133382274204).
2244625:2244639:S 10 Jan 2023 18:31:04.379 * Full resync from master: 9868c0da0bd965cf8506c53192c56e49e4355460:165719143532
2244625:2244639:S 10 Jan 2023 18:31:04.379 * Discarding previously cached master state.
2244625:2244639:S 10 Jan 2023 18:31:04.494 * MASTER <-> REPLICA sync: receiving 5732256 bytes from master to disk
2244625:2244639:S 10 Jan 2023 18:31:04.543 * MASTER <-> REPLICA sync: Loading DB in memory
2244625:2244639:S 10 Jan 2023 18:31:04.727 * Loading RDB produced by version 6.3.1
2244625:2244639:S 10 Jan 2023 18:31:04.727 * RDB age 0 seconds
2244625:2244639:S 10 Jan 2023 18:31:04.727 * RDB memory usage when created 12.65 Mb
2244625:2244639:S 10 Jan 2023 18:31:04.810 # Done loading RDB, keys loaded: 0, keys expired: 0.
2244625:2244639:S 10 Jan 2023 18:31:04.810 * RDB contains information on 1 masters
2244625:2244639:S 10 Jan 2023 18:31:04.811 * MASTER <-> REPLICA sync: Finished with success
2244625:2244639:S 10 Jan 2023 18:31:04.813 * Replica 10.70.32.242:6379 asks for synchronization
2244625:2244639:S 10 Jan 2023 18:31:04.813 * Unable to partial resync with replica 10.70.32.242:6379 for lack of backlog (Replica request was: 153590571136).
2244625:2244639:S 10 Jan 2023 18:31:04.813 # Warning: replica 10.70.32.242:6379 tried to PSYNC with an offset that is greater than the master replication offset.
2244625:2244639:S 10 Jan 2023 18:31:04.813 * Starting BGSAVE for SYNC with target: disk
2244625:2244639:S 10 Jan 2023 18:31:04.814 * Background saving started
2244625:2244643:S 10 Jan 2023 18:31:04.922 * DB saved on disk
2244625:2244643:S 10 Jan 2023 18:31:04.924 * RDB: 14 MB of memory used by copy-on-write
2244625:2244639:S 10 Jan 2023 18:31:05.014 * Background saving terminated with success
2244625:2244639:S 10 Jan 2023 18:31:05.051 * Synchronization with replica 10.70.32.242:6379 succeeded
2244625:2244639:S 10 Jan 2023 18:31:05.214 # Replication backlog is too small, resizing to: 2097152 bytes
2244625:2244639:S 10 Jan 2023 18:31:05.257 # Replication backlog is too small, resizing to: 4194304 bytes
2244625:2244639:S 10 Jan 2023 18:31:05.300 # Replication backlog is too small, resizing to: 8388608 bytes
2244625:2244639:S 10 Jan 2023 18:31:06.526 * Reclaiming 7340032 replication backlog bytes
2244625:2244639:S 10 Jan 2023 18:32:06.065 * 10000 changes in 60 seconds. Saving...
2244625:2244639:S 10 Jan 2023 18:32:06.065 * Background saving started
2244625:2245229:S 10 Jan 2023 18:32:06.183 * DB saved on disk
2244625:2245229:S 10 Jan 2023 18:32:06.185 * RDB: 17 MB of memory used by copy-on-write
2244625:2244639:S 10 Jan 2023 18:32:06.267 * Background saving terminated with success
Aditional information
- Ubuntu 18.04.6 LTS (Bionic Beaver)
- Running a replicated cluster, observed that we are unable to connect successfully to keydb after some days. Same experience with the CLI tool at such times. The only option is to force a restart of the two server instances. I got this crash on both servers while performing the restart today.
This may be related to issue #537
The only additions to /etc/keydb/keydb.conf on this server follows, similar to the other one:
requirepass "7eTA19aAa1mZ6"
masterauth "7eTA19aAa1mZ6"
# Generated by CONFIG REWRITE
user default on #39aa2357b415b3ecf8a52fed5ba73af82b3dc8aaa5753e3d3a6de8a900cc7c69 ~* &* +@all
replicaof 10.70.32.242 6379
active-replica yes
