search

Snapchat / KeyDB

A Multithreaded Fork of Redis
https://keydb.dev
BSD 3-Clause "New" or "Revised" License
11.52k stars 578 forks source link

[BUG] crash on json.get after upgrading to debian 12 stable #676

Open zboralski opened 1 year ago

zboralski commented 1 year ago

Describe the bug

My configuration was working perfectly until I upgraded the machine it was running on to debian 12 after it was released.

To reproduce

Send a simple json.get command.

Expected behavior

no crash

Additional information

=== KEYDB BUG REPORT START: Cut & paste starting from here === 1:136:M 16 Jun 2023 18:43:27.148 # === ASSERTION FAILED === 1:136:M 16 Jun 2023 18:43:27.148 # ==> module.cpp:650 'GlobalLocksAcquired()' is not true

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

Backtrace: /usr/bin/keydb-server 100.101.231.57:6379(moduleHandlePropagationAfterCommandCallback(RedisModuleCtx)+0xe5) [0x556b05eceb45] /usr/bin/keydb-server 100.101.231.57:6379(moduleFreeContext(RedisModuleCtx)+0xc) [0x556b05ecf4fc] /usr/bin/keydb-server 100.101.231.57:6379(rdbLoadObject(int, _rio, char, int, unsigned long)+0x1106) [0x556b05e50a66] /usr/bin/keydb-server 100.101.231.57:6379(+0x1abe56) [0x556b05e24e56] /usr/bin/keydb-server 100.101.231.57:6379(deserializeStoredObject(redisDbPersistentData const, char const, void const, unsigned long)+0xdb) [0x556b05e248ab] /usr/bin/keydb-server 100.101.231.57:6379(+0x1be529) [0x556b05e37529] /usr/bin/keydb-server 100.101.231.57:6379(RocksDBStorageProvider::retrieve(char const, unsigned long, std::function<void (char const, unsigned long, void const, unsigned long)>) const+0x199) [0x556b05f12539] /usr/bin/keydb-server 100.101.231.57:6379(StorageCache::retrieve(char, std::function<void (char const, unsigned long, void const, unsigned long)>) const+0x114) [0x556b05f19764] /usr/bin/keydb-server 100.101.231.57:6379(redisDbPersistentData::prefetchKeysAsync(client, parsed_command&)+0x514) [0x556b05e36754] /usr/bin/keydb-server 100.101.231.57:6379(+0x1a76c2) [0x556b05e206c2] /usr/bin/keydb-server 100.101.231.57:6379(readQueryFromClient(connection)+0x3e7) [0x556b05e16a07] /usr/bin/keydb-server 100.101.231.57:6379(connSocketEventHandler(aeEventLoop, int, void, int)+0x214) [0x556b05f0c214] /usr/bin/keydb-server 100.101.231.57:6379(ProcessEventCore+0xfd) [0x556b05de503d] /usr/bin/keydb-server 100.101.231.57:6379(aeProcessEvents+0x1a5) [0x556b05de8d75] /usr/bin/keydb-server 100.101.231.57:6379(aeMain+0x3e) [0x556b05de952e] /usr/bin/keydb-server 100.101.231.57:6379(workerThreadMain(void*)+0x190) [0x556b05e00670] /lib/x86_64-linux-gnu/libc.so.6(+0x88fd4) [0x7f852aca7fd4] /lib/x86_64-linux-gnu/libc.so.6(+0x1095bc) [0x7f852ad285bc]

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

Server

redis_version:6.3.3 redis_git_sha1:00000000 redis_git_dirty:0 redis_build_id:5201cb70a45ea433 redis_mode:standalone os:Linux 6.1.0-9-amd64 x86_64 arch_bits:64 multiplexing_api:epoll atomicvar_api:atomic-builtin gcc_version:12.2.0 process_id:1 process_supervised:no run_id:00f2d70a67951d295a208def6b362237945c7779 tcp_port:6379 server_time_usec:1686941007150800 uptime_in_seconds:281 uptime_in_days:0 hz:10 configured_hz:10 lru_clock:9219407 executable:/usr/bin/keydb-server config_file:/secrets/keydb.conf

Clients

connected_clients:5 cluster_connections:0 maxclients:10000 client_recent_max_input_buffer:136 client_recent_max_output_buffer:0 blocked_clients:0 tracking_clients:0 clients_in_timeout_table:0 current_client_thread:0 thread_0_clients:5 thread_1_clients:0 thread_2_clients:0 thread_3_clients:0

Memory

used_memory:12580096 used_memory_human:12.00M used_memory_rss:188190720 used_memory_rss_human:179.47M used_memory_peak:12693272 used_memory_peak_human:12.11M used_memory_peak_perc:99.11% used_memory_overhead:18199000 used_memory_startup:12422136 used_memory_dataset:18446744073703932712 used_memory_dataset_perc:11678110567104512.00% allocator_allocated:13914304 allocator_active:16187392 allocator_resident:21639168 total_system_memory:67333013504 total_system_memory_human:62.71G 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:34359738368 maxmemory_human:32.00G maxmemory_policy:allkeys-lru allocator_frag_ratio:1.16 allocator_frag_bytes:2273088 allocator_rss_ratio:1.34 allocator_rss_bytes:5451776 rss_overhead_ratio:8.70 rss_overhead_bytes:166551552 mem_fragmentation_ratio:15.02 mem_fragmentation_bytes:175660264 mem_not_counted_for_evict:0 mem_replication_backlog:0 mem_clients_slaves:0 mem_clients_normal:102480 mem_aof_buffer:0 mem_allocator:jemalloc-5.2.1 active_defrag_running:0 lazyfree_pending_objects:0 lazyfreed_objects:0 storage_provider:flash flash_memory:147595139

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:0 rdb_bgsave_in_progress:0 rdb_last_save_time:1686940726 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:3450 total_commands_processed:3666 instantaneous_ops_per_sec:0 total_net_input_bytes:613296 total_net_output_bytes:384368 instantaneous_input_kbps:0.01 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:283514 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:6882 dump_payload_sanitizations:0 total_reads_processed:7111 total_writes_processed:7106 instantaneous_lock_contention:0 avg_lock_contention:0.031250 storage_provider_read_hits:0 storage_provider_read_misses:0

Replication

role:master connected_slaves:0 master_failover_state:no-failover master_replid:551bd520c6995d66376c660d2818735915466f04 master_replid2:0000000000000000000000000000000000000000 master_repl_offset:0 second_repl_offset:-1 repl_backlog_active:0 repl_backlog_size:1048576 repl_backlog_first_byte_offset:0 repl_backlog_histlen:0

CPU

used_cpu_sys:0.887207 used_cpu_user:1.276566 used_cpu_sys_children:0.000000 used_cpu_user_children:0.000000 server_threads:4 long_lock_waits:0 used_cpu_sys_main_thread:0.401210 used_cpu_user_main_thread:0.687179

Modules

module:name=graph,ver=21010,api=1,filters=0,usedby=[],using=[ReJSON],options=[] module:name=timeseries,ver=10810,api=1,filters=0,usedby=[],using=[],options=[] module:name=bf,ver=20405,api=1,filters=0,usedby=[],using=[],options=[] module:name=ReJSON,ver=20407,api=1,filters=0,usedby=[graph],using=[],options=[handle-io-errors]

Commandstats

cmdstat_auth:calls=9,usec=29,usec_per_call=3.22,rejected_calls=0,failed_calls=0 cmdstat_command:calls=1,usec=985,usec_per_call=985.00,rejected_calls=0,failed_calls=0 cmdstat_client:calls=0,usec=0,usec_per_call=0.00,rejected_calls=3441,failed_calls=0 cmdstat_acl:calls=3,usec=182,usec_per_call=60.67,rejected_calls=0,failed_calls=0 cmdstat_ping:calls=211,usec=213,usec_per_call=1.01,rejected_calls=0,failed_calls=0 cmdstat_hello:calls=3441,usec=34954,usec_per_call=10.16,rejected_calls=0,failed_calls=3441 cmdstat_info:calls=1,usec=8,usec_per_call=8.00,rejected_calls=0,failed_calls=0

Errorstats

errorstat_NOAUTH:count=3441 errorstat_WRONGPASS:count=3441

Cluster

cluster_enabled:0

Keyspace

db0:keys=141757,expires=0,avg_ttl=0,cached_keys=0

KeyDB

mvcc_depth:0

------ CLIENT LIST OUTPUT ------ id=362 addr=100.101.231.57:44440 laddr=100.101.231.57:6379 fd=115 name= age=265 idle=2 flags=N 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=ping user=default redir=-1 id=363 addr=100.101.231.57:44456 laddr=100.101.231.57:6379 fd=116 name= age=265 idle=1 flags=N 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=ping user=default redir=-1 id=360 addr=100.101.231.57:44416 laddr=100.101.231.57:6379 fd=110 name= age=265 idle=5 flags=N 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=ping user=default redir=-1 id=361 addr=100.101.231.57:44424 laddr=100.101.231.57:6379 fd=112 name= age=265 idle=7 flags=N 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=ping user=default redir=-1 id=3461 addr=100.99.212.94:63475 laddr=100.101.231.57:6379 fd=117 name= age=3 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=45 qbuf-free=40909 argv-mem=28 obl=0 oll=0 omem=0 tot-mem=61476 events=r cmd=command user=V_ROOT_ADMIN_JNZ6UPKI2TUNMXTZKDYJ_1686941000 redir=-1

------ MODULES INFO OUTPUT ------

graph_executing commands

ReJSON_trace

ReJSON_trace: 0: redis_module::base_info_func 1: rejson::__info_func 2: _Z18modulesCollectInfoPcPKcii 3: _Z14logModulesInfov 4: _serverAssert 5: _Z43moduleHandlePropagationAfterCommandCallbackP14RedisModuleCtx 6: _Z17moduleFreeContextP14RedisModuleCtx 7: _Z13rdbLoadObjectiP4_rioPcPim 8: 9: _Z23deserializeStoredObjectPK21redisDbPersistentDataPKcPKvm 10: 11: _ZNK22RocksDBStorageProvider8retrieveEPKcmSt8functionIFvS1_mPKvmEE 12: _ZNK12StorageCache8retrieveEPcSt8functionIFvPKcmPKvmEE 13: _ZN21redisDbPersistentData17prefetchKeysAsyncEP6clientR14parsed_command 14: 15: _Z19readQueryFromClientP10connection 16: _Z22connSocketEventHandlerP11aeEventLoopiPvi 17: ProcessEventCore 18: aeProcessEvents 19: aeMain 20: _Z16workerThreadMainPv 21: 22:

------ FAST MEMORY TEST ------ 1:136:M 16 Jun 2023 18:43:27.153 # main thread terminated 1:136:M 16 Jun 2023 18:43:27.153 # Bio thread for job type #0 terminated 1:136:M 16 Jun 2023 18:43:27.153 # Bio thread for job type #1 terminated 1:136:M 16 Jun 2023 18:43:27.153 # 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.

zboralski commented 1 year ago

It is also a problem in Debian 11 after downgrading.

It seems to be a problem related to using flash... which is weird because it was working perfectly and it doesn't stopped working

if I create a new entry using json.set... I can read it... but if I try to read any of the old entry I get this crash:

=== KEYDB BUG REPORT START: Cut & paste starting from here === 10460:10637:M 19 Jun 2023 22:40:05.999 # === ASSERTION FAILED === 10460:10637:M 19 Jun 2023 22:40:05.999 # ==> module.cpp:650 'GlobalLocksAcquired()' is not true

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

Backtrace: keydb-server :6379(moduleHandlePropagationAfterCommandCallback(RedisModuleCtx)+0xe5) [0x55b7345afce5] keydb-server :6379(moduleFreeContext(RedisModuleCtx)+0xc) [0x55b7345afe1c] keydb-server :6379(rdbLoadObject(int, _rio, char, int, unsigned long)+0x15ee) [0x55b73453282e] keydb-server :6379(+0x1a0a8b) [0x55b734506a8b] keydb-server :6379(deserializeStoredObject(redisDbPersistentData const, char const, void const, unsigned long)+0xd5) [0x55b7345061c5] keydb-server :6379(+0x1b2a28) [0x55b734518a28] keydb-server :6379(RocksDBStorageProvider::retrieve(char const, unsigned long, std::function<void (char const, unsigned long, void const, unsigned long)>) const+0x190) [0x55b7345f3340] keydb-server :6379(StorageCache::retrieve(char, std::function<void (char const, unsigned long, void const, unsigned long)>) const+0x11c) [0x55b7345f94ac] keydb-server :6379(redisDbPersistentData::prefetchKeysAsync(client, parsed_command&)+0x50b) [0x55b734517bab] keydb-server :6379(+0x19c092) [0x55b734502092] keydb-server :6379(readQueryFromClient(connection)+0x3e2) [0x55b7344f80d2] keydb-server :6379(connSocketEventHandler(aeEventLoop, int, void, int)+0x1d0) [0x55b7345ecae0] keydb-server :6379(ProcessEventCore+0x103) [0x55b7344c5983] keydb-server :6379(aeProcessEvents+0x175) [0x55b7344c98f5] keydb-server :6379(aeMain+0x3e) [0x55b7344ca1fe] keydb-server :6379(workerThreadMain(void*)+0x1a0) [0x55b7344e1b00] /lib/x86_64-linux-gnu/libpthread.so.0(+0x7ea7) [0x7f0d6ae0eea7] /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f0d6ad2ea2f]

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

Server

redis_version:6.3.3 redis_git_sha1:00000000 redis_git_dirty:0 redis_build_id:23fdcae88c569b26 redis_mode:standalone os:Linux 5.10.0-23-amd64 x86_64 arch_bits:64 multiplexing_api:epoll atomicvar_api:atomic-builtin gcc_version:10.2.1 process_id:10460 process_supervised:no run_id:23121439baf0e03fe20ec5c249f0001ea0907e63 tcp_port:6379 server_time_usec:1687207206001390 uptime_in_seconds:42 uptime_in_days:0 hz:10 configured_hz:10 lru_clock:9485605 executable:/etc/keydb/keydb-server config_file:/etc/keydb/keydb.conf

Clients

connected_clients:1 cluster_connections:0 maxclients:10000 client_recent_max_input_buffer:24 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 thread_2_clients:0 thread_3_clients:0

Memory

used_memory:7172592 used_memory_human:6.84M used_memory_rss:79712256 used_memory_rss_human:76.02M used_memory_peak:7244008 used_memory_peak_human:6.91M used_memory_peak_perc:99.01% used_memory_overhead:8653856 used_memory_startup:7099656 used_memory_dataset:18446744073708070352 used_memory_dataset_perc:25291685869125632.00% allocator_allocated:9062880 allocator_active:10731520 allocator_resident:19070976 total_system_memory:67404398592 total_system_memory_human:62.78G 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:34359738368 maxmemory_human:32.00G maxmemory_policy:allkeys-lru allocator_frag_ratio:1.18 allocator_frag_bytes:1668640 allocator_rss_ratio:1.78 allocator_rss_bytes:8339456 rss_overhead_ratio:4.18 rss_overhead_bytes:60641280 mem_fragmentation_ratio:11.18 mem_fragmentation_bytes:72585464 mem_not_counted_for_evict:0 mem_replication_backlog:0 mem_clients_slaves:0 mem_clients_normal:20504 mem_aof_buffer:0 mem_allocator:jemalloc-5.2.1 active_defrag_running:0 lazyfree_pending_objects:0 lazyfreed_objects:0 storage_provider:flash flash_memory:41017041

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:1 rdb_bgsave_in_progress:0 rdb_last_save_time:1687207164 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:1 total_commands_processed:8 instantaneous_ops_per_sec:0 total_net_input_bytes:271 total_net_output_bytes:1451496 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:2 keyspace_misses:76477 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:0 dump_payload_sanitizations:0 total_reads_processed:8 total_writes_processed:7 instantaneous_lock_contention:0 avg_lock_contention:0.000000 storage_provider_read_hits:0 storage_provider_read_misses:3

Replication

role:master connected_slaves:0 master_failover_state:no-failover master_replid:866438e886adb0fb878506d7ac706112ffd71dab master_replid2:0000000000000000000000000000000000000000 master_repl_offset:0 second_repl_offset:-1 repl_backlog_active:0 repl_backlog_size:1048576 repl_backlog_first_byte_offset:0 repl_backlog_histlen:0

CPU

used_cpu_sys:0.076009 used_cpu_user:0.271104 used_cpu_sys_children:0.000000 used_cpu_user_children:0.000000 server_threads:4 long_lock_waits:0 used_cpu_sys_main_thread:0.014039 used_cpu_user_main_thread:0.080725

Modules

module:name=ReJSON,ver=20407,api=1,filters=0,usedby=[graph],using=[],options=[handle-io-errors] module:name=graph,ver=21010,api=1,filters=0,usedby=[],using=[ReJSON],options=[] module:name=timeseries,ver=10810,api=1,filters=0,usedby=[],using=[],options=[] module:name=bf,ver=20405,api=1,filters=0,usedby=[],using=[],options=[]

Commandstats

cmdstat_info:calls=1,usec=4,usec_per_call=4.00,rejected_calls=0,failed_calls=0 cmdstat_get:calls=1,usec=9,usec_per_call=9.00,rejected_calls=0,failed_calls=0 cmdstat_command:calls=1,usec=900,usec_per_call=900.00,rejected_calls=0,failed_calls=0 cmdstat_json.set:calls=1,usec=268,usec_per_call=268.00,rejected_calls=0,failed_calls=0 cmdstat_json.get:calls=2,usec=55,usec_per_call=27.50,rejected_calls=0,failed_calls=0 cmdstat_keys:calls=2,usec=60,usec_per_call=30.00,rejected_calls=0,failed_calls=0

Errorstats

Cluster

cluster_enabled:0

Keyspace

db0:keys=38239,expires=0,avg_ttl=0,cached_keys=2

KeyDB

mvcc_depth:0

------ CLIENT LIST OUTPUT ------ id=12 addr=127.0.0.1:48630 laddr=127.0.0.1:6379 fd=161 name= age=29 idle=1 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=45 qbuf-free=40909 argv-mem=28 obl=0 oll=0 omem=0 tot-mem=61484 events=r cmd=keys user=default redir=-1

------ MODULES INFO OUTPUT ------

ReJSON_trace

ReJSON_trace: 0: redis_module::base_info_func 1: rejson::__info_func 2: _Z18modulesCollectInfoPcPKcii 3: _Z14logModulesInfov 4: _serverAssert 5: _Z43moduleHandlePropagationAfterCommandCallbackP14RedisModuleCtx 6: _Z17moduleFreeContextP14RedisModuleCtx 7: _Z13rdbLoadObjectiP4_rioPcPim 8: 9: _Z23deserializeStoredObjectPK21redisDbPersistentDataPKcPKvm 10: 11: _ZNK22RocksDBStorageProvider8retrieveEPKcmSt8functionIFvS1_mPKvmEE 12: _ZNK12StorageCache8retrieveEPcSt8functionIFvPKcmPKvmEE 13: _ZN21redisDbPersistentData17prefetchKeysAsyncEP6clientR14parsed_command 14: 15: _Z19readQueryFromClientP10connection 16: _Z22connSocketEventHandlerP11aeEventLoopiPvi 17: ProcessEventCore 18: aeProcessEvents 19: aeMain 20: _Z16workerThreadMainPv 21: start_thread 22: clone

graph_executing commands

------ FAST MEMORY TEST ------ 10460:10637:M 19 Jun 2023 22:40:06.004 # main thread terminated 10460:10637:M 19 Jun 2023 22:40:06.004 # Bio thread for job type #0 terminated 10460:10637:M 19 Jun 2023 22:40:06.004 # Bio thread for job type #1 terminated 10460:10637:M 19 Jun 2023 22:40:06.004 # 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. ===