[CRASH] Lua SCAN with COUNT 100

[jbonjean]

Crash report

1:16:S 23 Jun 2022 15:25:01.423 * Background saving terminated with success
1:16:S 23 Jun 2022 15:25:01.424 * Synchronization with replica 10.42.2.4:6379 succeeded
1:16:S 23 Jun 2022 15:25:01.424 * Synchronization with replica 10.42.1.4:6379 succeeded


=== KEYDB BUG REPORT START: Cut & paste starting from here ===
1:16:S 23 Jun 2022 15:26:01.691 # === ASSERTION FAILED ===
1:16:S 23 Jun 2022 15:26:01.691 # ==> scripting.cpp:780 '(c->flags & CLIENT_BLOCKED) == 0' is not true

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

Backtrace:
keydb-server 0.0.0.0:6379(luaRedisGenericCommand(lua_State*, int)+0xd6a) [0x5609f77221fa]
keydb-server 0.0.0.0:6379(+0x183998) [0x5609f7783998]
keydb-server 0.0.0.0:6379(+0x18d212) [0x5609f778d212]
keydb-server 0.0.0.0:6379(+0x183e5d) [0x5609f7783e5d]
keydb-server 0.0.0.0:6379(+0x18317e) [0x5609f778317e]
keydb-server 0.0.0.0:6379(+0x183fcb) [0x5609f7783fcb]
keydb-server 0.0.0.0:6379(lua_pcall+0x58) [0x5609f77816e8]
keydb-server 0.0.0.0:6379(evalGenericCommand(client*, int)+0x2db) [0x5609f771feab]
keydb-server 0.0.0.0:6379(call(client*, int)+0xb1) [0x5609f773e9d1]
keydb-server 0.0.0.0:6379(processCommand(client*, int)+0x954) [0x5609f773fb54]
keydb-server 0.0.0.0:6379(processCommandAndResetClient(client*, int)+0x66) [0x5609f76a14e6]
keydb-server 0.0.0.0:6379(processInputBuffer(client*, bool, int)+0x174) [0x5609f76a7844]
keydb-server 0.0.0.0:6379(processClients()+0xd9) [0x5609f76a79d9]
keydb-server 0.0.0.0:6379(+0x1378d2) [0x5609f77378d2]
keydb-server 0.0.0.0:6379(beforeSleep(aeEventLoop*)+0x150) [0x5609f7666d30]
keydb-server 0.0.0.0:6379(aeProcessEvents+0x10b) [0x5609f765ea1b]
keydb-server 0.0.0.0:6379(aeMain+0x47) [0x5609f7668467]
keydb-server 0.0.0.0:6379(workerThreadMain(void*)+0x73) [0x5609f77384b3]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7fefacd2e6db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fefaca5761f]

------ INFO OUTPUT ------
# Server
redis_version:6.3.1
redis_git_sha1:ee16abf0
redis_git_dirty:1
redis_build_id:46da54e1e1000581
redis_mode:standalone
os:Linux 5.11.0-49-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:7.5.0
process_id:1
process_supervised:no
run_id:7f071fdaad4bbaaf1792e99f55eb560ce7294279
tcp_port:6379
server_time_usec:1655997961692008
uptime_in_seconds:85
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:11830793
executable:/data/keydb-server
config_file:/etc/keydb/redis.conf

# Clients
connected_clients:3
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:48
client_recent_max_output_buffer:0
blocked_clients:1
tracking_clients:0
clients_in_timeout_table:0
current_client_thread:0
thread_0_clients:5
thread_1_clients:0

# Memory
used_memory:3486728
used_memory_human:3.33M
used_memory_rss:16908288
used_memory_rss_human:16.12M
used_memory_peak:3507776
used_memory_peak_human:3.35M
used_memory_peak_perc:99.40%
used_memory_overhead:3264592
used_memory_startup:2092680
used_memory_dataset:222136
used_memory_dataset_perc:15.93%
allocator_allocated:4310208
allocator_active:4923392
allocator_resident:9691136
total_system_memory:33414451200
total_system_memory_human:31.12G
used_memory_lua:114688
used_memory_lua_human:112.00K
used_memory_scripts:32816
used_memory_scripts_human:32.05K
number_of_cached_scripts:22
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.14
allocator_frag_bytes:613184
allocator_rss_ratio:1.97
allocator_rss_bytes:4767744
rss_overhead_ratio:1.74
rss_overhead_bytes:7217152
mem_fragmentation_ratio:5.08
mem_fragmentation_bytes:13580656
mem_not_counted_for_evict:1048576
mem_replication_backlog:1048576
mem_clients_slaves:41024
mem_clients_normal:41056
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:17702912
current_cow_size_age:60
current_fork_perc:0.00
current_save_keys_processed:1
current_save_keys_total:0
rdb_changes_since_last_save:14
rdb_bgsave_in_progress:0
rdb_last_save_time:1655997901
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:17833984
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:33
total_commands_processed:326
instantaneous_ops_per_sec:3
total_net_input_bytes:37975
total_net_output_bytes:52165
instantaneous_input_kbps:0.08
instantaneous_output_kbps:0.10
rejected_connections:0
sync_full:2
sync_partial_ok:0
sync_partial_err:2
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:0
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:2
dump_payload_sanitizations:0
total_reads_processed:266
total_writes_processed:274
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:up
connected_masters:2
master_host:keydb-1.keydb-headless
master_port:6379
master_link_status:up
master_last_io_seconds_ago:0
master_sync_in_progress:0
slave_read_repl_offset:268032
slave_repl_offset:268032
master_1_host:keydb-2.keydb-headless
master_1_port:6379
master_1_link_status:up
master_1_last_io_seconds_ago:0
master_1_sync_in_progress:0
slave_read_repl_offset:267791
slave_repl_offset:267791
slave_priority:100
slave_read_only:0
replica_announced:1
connected_slaves:2
slave0:ip=10.42.2.4,port=6379,state=online,offset=7497,lag=0
slave1:ip=10.42.1.4,port=6379,state=online,offset=7497,lag=0
master_failover_state:no-failover
master_replid:a648b366a86d3b8a64ebdb64935001cebe38bf92
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:8083
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:1
repl_backlog_histlen:8083

# CPU
used_cpu_sys:0.141372
used_cpu_user:0.184015
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000535
server_threads:2
long_lock_waits:0
used_cpu_sys_main_thread:0.060212
used_cpu_user_main_thread:0.090318

# Modules

# Commandstats
cmdstat_psync:calls=2,usec=241,usec_per_call=120.50,rejected_calls=0,failed_calls=0
cmdstat_replping:calls=2,usec=2,usec_per_call=1.00,rejected_calls=0,failed_calls=0
cmdstat_evalsha:calls=3,usec=33,usec_per_call=11.00,rejected_calls=0,failed_calls=2
cmdstat_KEYDB.MVCCRESTORE:calls=8,usec=11,usec_per_call=1.38,rejected_calls=0,failed_calls=0
cmdstat_script:calls=2,usec=64,usec_per_call=32.00,rejected_calls=0,failed_calls=0
cmdstat_replconf:calls=126,usec=162,usec_per_call=1.29,rejected_calls=0,failed_calls=0
cmdstat_scan:calls=2,usec=16,usec_per_call=8.00,rejected_calls=0,failed_calls=0
cmdstat_rreplay:calls=128,usec=510,usec_per_call=3.98,rejected_calls=0,failed_calls=0
cmdstat_get:calls=2,usec=4,usec_per_call=2.00,rejected_calls=0,failed_calls=0
cmdstat_set:calls=6,usec=44,usec_per_call=7.33,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=45,usec=30,usec_per_call=0.67,rejected_calls=0,failed_calls=0

# Errorstats
errorstat_NOSCRIPT:count=2

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=4,expires=1,avg_ttl=6715094416515420160,cached_keys=4

# KeyDB
mvcc_depth:1

------ CLIENT LIST OUTPUT ------
id=6 addr=10.42.2.4:6379 laddr=10.42.0.6:32783 fd=17 name= age=85 idle=0 flags=M db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=40954 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=61480 events=r cmd=rreplay user=(superuser) redir=-1
id=5 addr=10.42.1.4:6379 laddr=10.42.0.6:45967 fd=19 name= age=85 idle=0 flags=M db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=40954 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=61480 events=r cmd=rreplay user=(superuser) redir=-1
id=12 addr=10.42.2.4:33531 laddr=10.42.0.6:6379 fd=20 name= age=60 idle=0 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=13 addr=10.42.1.4:35829 laddr=10.42.0.6:6379 fd=23 name= age=60 idle=0 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=40954 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=61464 events=r cmd=replconf user=default redir=-1
id=41 addr=127.0.0.1:34534 laddr=127.0.0.1:6379 fd=24 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=40954 argv-mem=48 obl=0 oll=0 omem=0 tot-mem=61512 events=r cmd=evalsha user=default redir=-1

------ CURRENT CLIENT INFO ------
id=41 addr=127.0.0.1:34534 laddr=127.0.0.1:6379 fd=24 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=40954 argv-mem=48 obl=0 oll=0 omem=0 tot-mem=61512 events=r cmd=evalsha user=default redir=-1
argv[0]: 'EVALSHA'
argv[1]: '391566a43cfa2ecb44b2ea60074086e4276ae0c2'
argv[2]: '0'

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

------ FAST MEMORY TEST ------
1:16:S 23 Jun 2022 15:26:01.692 # main thread terminated
1:16:S 23 Jun 2022 15:26:01.692 # Bio thread for job type #0 terminated
1:16:S 23 Jun 2022 15:26:01.692 # Bio thread for job type #1 terminated
1:16:S 23 Jun 2022 15:26:01.692 # 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.

Aditional information

1. k3d v5.4.3, 3 agents, 1 server.
2. Helm chart: https://artifacthub.io/packages/helm/enapter/keydb (0.39.0, Docker image eqalpha/keydb:x86_64_v6.3.1).
3. Multi-master enabled, 3 nodes.

Reproducer

• Works:

redis.call("SCAN", "0", "MATCH", "key*", "COUNT", 99)

• Crashes:

redis.call("SCAN", "0", "MATCH", "key*", "COUNT", 100)

[JohnSully]

We attempt to run the command in background but this is not supported with eval as we need to be atomic. The fix is to disable running in the background and force the foreground version. 100 is the heuristic where scan runs in the background which is why it crashes there.

Fix change 1948f21