Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[CRASH] valkey crashed after close same key twice via invoking ValkeyModule_CloseKey() #1775

Open
zh1029 opened this issue Feb 25, 2025 · 2 comments
Open

[CRASH] valkey crashed after close same key twice via invoking ValkeyModule_CloseKey() #1775

zh1029 opened this issue Feb 25, 2025 · 2 comments
Assignees
@sungming2

Comments

@zh1029
Copy link

zh1029 commented Feb 25, 2025

Crash report

valkey 8.0.2

=== VALKEY BUG REPORT START: Cut & paste starting from here ===
26099:M 25 Feb 2025 02:13:46.791 # ------------------------------------------------
26099:M 25 Feb 2025 02:13:46.791 # !!! Software Failure. Press left mouse button to continue
26099:M 25 Feb 2025 02:13:46.791 # Guru Meditation: decrRefCount against refcount <= 0 #object.c:396

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

26102 bio_lazy_free
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26101 bio_aof
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26100 bio_close_file
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26099 valkey-server *
./src/valkey-server 127.0.0.1:6379[0x48e49a]
./src/valkey-server 127.0.0.1:6379[0x49bdcc]
./src/valkey-server 127.0.0.1:6379(processInputBuffer+0x15b)[0x4935ab]
./src/valkey-server 127.0.0.1:6379(readQueryFromClient+0xa0)[0x493770]
./src/valkey-server 127.0.0.1:6379[0x5b38ba]
./src/valkey-server 127.0.0.1:6379(aeMain+0x8a)[0x45ecea]
./src/valkey-server 127.0.0.1:6379(main+0x4b4)[0x454054]
/lib64/libc.so.6(+0x2a088)[0x7f05aa85f088]
/lib64/libc.so.6(__libc_start_main+0x8b)[0x7f05aa85f14b]
./src/valkey-server 127.0.0.1:6379(_start+0x25)[0x4546b5]

4/4 expected stacktraces.

------ STACK TRACE DONE ------

------ INFO OUTPUT ------
# Server
redis_version:7.2.4
server_name:valkey
valkey_version:8.0.2
redis_git_sha1:00000000
redis_git_dirty:1
redis_build_id:5ef9bd703e631fff
server_mode:standalone
os:Linux 5.14.0-503.14.1.el9_5.x86_64 x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
gcc_version:14.2.1
process_id:26099
process_supervised:no
run_id:712883f285f5216e2bedd9aadc1f59477a282b49
tcp_port:6379
server_time_usec:1740449626790755
uptime_in_seconds:96
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:12396378
executable:/trunk/chenyan/valkey-8.0.2/./src/valkey-server
config_file:/trunk/chenyan/valkey-8.0.2/./valkey.conf
io_threads_active:0
availability_zone:
listener0:name=tcp,bind=127.0.0.1,bind=-::1,port=6379

# Clients
connected_clients:1
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
pubsub_clients:0
watching_clients:0
clients_in_timeout_table:0
total_watched_keys:0
total_blocking_keys:0
total_blocking_keys_on_nokey:0

# Memory
used_memory:1296576
used_memory_human:1.24M
used_memory_rss:13082624
used_memory_rss_human:12.48M
used_memory_peak:1296576
used_memory_peak_human:1.24M
used_memory_peak_perc:100.16%
used_memory_overhead:973224
used_memory_startup:972728
used_memory_dataset:323352
used_memory_dataset_perc:99.85%
allocator_allocated:1704800
allocator_active:1863680
allocator_resident:5144576
allocator_muzzy:0
total_system_memory:24930467840
total_system_memory_human:23.22G
used_memory_lua:31744
used_memory_vm_eval:31744
used_memory_lua_human:31.00K
used_memory_scripts_eval:0
number_of_cached_scripts:0
number_of_functions:0
number_of_libraries:0
used_memory_vm_functions:33792
used_memory_vm_total:65536
used_memory_vm_total_human:64.00K
used_memory_functions:184
used_memory_scripts:184
used_memory_scripts_human:184B
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.09
allocator_frag_bytes:158880
allocator_rss_ratio:2.76
allocator_rss_bytes:3280896
rss_overhead_ratio:2.54
rss_overhead_bytes:7938048
mem_fragmentation_ratio:12.50
mem_fragmentation_bytes:12035680
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_total_replication_buffers:0
mem_clients_slaves:0
mem_clients_normal:0
mem_cluster_links:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.3.0
mem_overhead_db_hashtable_rehashing:0
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0

# Persistence
loading:0
async_loading:0
current_cow_peak: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:1740449530
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_saves:0
rdb_last_cow_size:0
rdb_last_load_keys_expired:0
rdb_last_load_keys_loaded: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_rewrites:0
aof_rewrites_consecutive_failures:0
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:2
total_commands_processed:4
instantaneous_ops_per_sec:0
total_net_input_bytes:121
total_net_output_bytes:72
total_net_repl_input_bytes:0
total_net_repl_output_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
instantaneous_input_repl_kbps:0.00
instantaneous_output_repl_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:1
evicted_keys:0
evicted_clients:0
evicted_scripts:0
total_eviction_exceeded_time:0
current_eviction_exceeded_time:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
pubsubshard_channels: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
total_active_defrag_time:0
current_active_defrag_time:0
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:1
dump_payload_sanitizations:0
total_reads_processed:6
total_writes_processed:4
io_threaded_reads_processed:0
io_threaded_writes_processed:0
io_threaded_freed_objects:0
io_threaded_poll_processed:0
io_threaded_total_prefetch_batches:0
io_threaded_total_prefetch_entries:0
client_query_buffer_limit_disconnections:0
client_output_buffer_limit_disconnections:0
reply_buffer_shrinks:1
reply_buffer_expands:0
eventloop_cycles:963
eventloop_duration_sum:184386
eventloop_duration_cmd_sum:1182
instantaneous_eventloop_cycles_per_sec:9
instantaneous_eventloop_duration_usec:173
acl_access_denied_auth:0
acl_access_denied_cmd:0
acl_access_denied_key:0
acl_access_denied_channel:0

# Replication
role:master
connected_slaves:0
replicas_waiting_psync:0
master_failover_state:no-failover
master_replid:1d1c0bbdb37dc73d23a599c88b0c5281953f65b2
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:10485760
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:0.076909
used_cpu_user:0.136069
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
used_cpu_sys_main_thread:0.076747
used_cpu_user_main_thread:0.135784

# Modules
module:name=seqList,ver=1,api=1,filters=0,usedby=[],using=[],options=[]
module:name=exstrings,ver=1,api=1,filters=0,usedby=[],using=[],options=[]

# Commandstats
cmdstat_command|docs:calls=1,usec=1156,usec_per_call=1156.00,rejected_calls=0,failed_calls=0
cmdstat_keys:calls=1,usec=4,usec_per_call=4.00,rejected_calls=0,failed_calls=0
cmdstat_cy.test:calls=1,usec=13,usec_per_call=13.00,rejected_calls=0,failed_calls=0
cmdstat_set:calls=1,usec=9,usec_per_call=9.00,rejected_calls=0,failed_calls=0

# Errorstats
errorstat_ERR:count=1

# Latencystats
latency_percentiles_usec_command|docs:p50=1163.263,p99=1163.263,p99.9=1163.263
latency_percentiles_usec_keys:p50=4.015,p99=4.015,p99.9=4.015
latency_percentiles_usec_cy.test:p50=13.055,p99=13.055,p99.9=13.055
latency_percentiles_usec_set:p50=9.023,p99=9.023,p99.9=9.023

# Cluster
cluster_enabled:0

# Keyspace

------ CLIENT LIST OUTPUT ------
id=5 addr=127.0.0.1:43544 laddr=127.0.0.1:6379 fd=10 name=*redacted* age=0 idle=0 flags=N db=0 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=11 multi-mem=0 rbs=16384 rbp=16384 obl=16384 oll=10 omem=205040 tot-mem=222347 events=r cmd=command|docs user=*redacted* redir=-1 resp=2 lib-name= lib-ver= tot-net-in=27 tot-net-out=0 tot-cmds=1

------ CURRENT CLIENT INFO ------
id=5 addr=127.0.0.1:43544 laddr=127.0.0.1:6379 fd=10 name=*redacted* age=0 idle=0 flags=N db=0 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=11 multi-mem=0 rbs=16384 rbp=16384 obl=16384 oll=10 omem=205040 tot-mem=222347 events=r cmd=command|docs user=*redacted* redir=-1 resp=2 lib-name= lib-ver= tot-net-in=27 tot-net-out=0 tot-cmds=1
argc: '2'
26099:M 25 Feb 2025 02:13:46.799 # valkey 8.0.2 crashed by signal: 11, si_code: 1
26099:M 25 Feb 2025 02:13:46.799 # Accessing address: 0xffffffffffffffff
26099:M 25 Feb 2025 02:13:46.799 # Crashed running the instruction at: 0x505974

------ STACK TRACE ------
EIP:
./src/valkey-server 127.0.0.1:6379(logCurrentClient+0x144)[0x505974]

26102 bio_lazy_free
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26100 bio_close_file
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26099 valkey-server *
/lib64/libc.so.6(+0x40cf0)[0x7f05aa875cf0]
./src/valkey-server 127.0.0.1:6379(logCurrentClient+0x144)[0x505974]
./src/valkey-server 127.0.0.1:6379(printCrashReport+0x29)[0x505d39]
./src/valkey-server 127.0.0.1:6379(_serverPanic+0x236)[0x506446]
./src/valkey-server 127.0.0.1:6379[0x48e49a]
./src/valkey-server 127.0.0.1:6379[0x49bdcc]
./src/valkey-server 127.0.0.1:6379(processInputBuffer+0x15b)[0x4935ab]
./src/valkey-server 127.0.0.1:6379(readQueryFromClient+0xa0)[0x493770]
./src/valkey-server 127.0.0.1:6379[0x5b38ba]
./src/valkey-server 127.0.0.1:6379(aeMain+0x8a)[0x45ecea]
./src/valkey-server 127.0.0.1:6379(main+0x4b4)[0x454054]
/lib64/libc.so.6(+0x2a088)[0x7f05aa85f088]
/lib64/libc.so.6(__libc_start_main+0x8b)[0x7f05aa85f14b]
./src/valkey-server 127.0.0.1:6379(_start+0x25)[0x4546b5]

26101 bio_aof
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

4/4 expected stacktraces.

------ STACK TRACE DONE ------

------ REGISTERS ------
26099:M 25 Feb 2025 02:13:46.807 #
RAX:00007f05aa29e140 RBX:0000000000000000
RCX:0000000000000400 RDX:0000000000000002
RDI:00007f05aa29e140 RSI:0000000000000000
RBP:00007ffe4469d4b0 RSP:00007ffe4469d470
R8 :0000000000000002 R9 :00000000ffffffff
R10:0000000000000000 R11:0000000000000246
R12:00007f05aa29e140 R13:00007ffe4469d5a0
R14:00007f05aa398a80 R15:0000000000000000
RIP:0000000000505974 EFL:0000000000010202
CSGSFS:002b000000000033
26099:M 25 Feb 2025 02:13:46.807 * hide-user-data-from-log is on, skip logging stack content to avoid spilling user data.

------ INFO OUTPUT ------
# Server
redis_version:7.2.4
server_name:valkey
valkey_version:8.0.2
redis_git_sha1:00000000
redis_git_dirty:1
redis_build_id:5ef9bd703e631fff
server_mode:standalone
os:Linux 5.14.0-503.14.1.el9_5.x86_64 x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
gcc_version:14.2.1
process_id:26099
process_supervised:no
run_id:712883f285f5216e2bedd9aadc1f59477a282b49
tcp_port:6379
server_time_usec:1740449626790755
uptime_in_seconds:96
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:12396378
executable:/trunk/chenyan/valkey-8.0.2/./src/valkey-server
config_file:/trunk/chenyan/valkey-8.0.2/./valkey.conf
io_threads_active:0
availability_zone:
listener0:name=tcp,bind=127.0.0.1,bind=-::1,port=6379

# Clients
connected_clients:1
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
pubsub_clients:0
watching_clients:0
clients_in_timeout_table:0
total_watched_keys:0
total_blocking_keys:0
total_blocking_keys_on_nokey:0

# Memory
used_memory:1296616
used_memory_human:1.24M
used_memory_rss:13082624
used_memory_rss_human:12.48M
used_memory_peak:1296616
used_memory_peak_human:1.24M
used_memory_peak_perc:100.00%
used_memory_overhead:973224
used_memory_startup:972728
used_memory_dataset:323392
used_memory_dataset_perc:99.85%
allocator_allocated:1704800
allocator_active:1863680
allocator_resident:5144576
allocator_muzzy:0
total_system_memory:24930467840
total_system_memory_human:23.22G
used_memory_lua:31744
used_memory_vm_eval:31744
used_memory_lua_human:31.00K
used_memory_scripts_eval:0
number_of_cached_scripts:0
number_of_functions:0
number_of_libraries:0
used_memory_vm_functions:33792
used_memory_vm_total:65536
used_memory_vm_total_human:64.00K
used_memory_functions:184
used_memory_scripts:184
used_memory_scripts_human:184B
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.09
allocator_frag_bytes:158880
allocator_rss_ratio:2.76
allocator_rss_bytes:3280896
rss_overhead_ratio:2.54
rss_overhead_bytes:7938048
mem_fragmentation_ratio:12.50
mem_fragmentation_bytes:12035680
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_total_replication_buffers:0
mem_clients_slaves:0
mem_clients_normal:0
mem_cluster_links:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.3.0
mem_overhead_db_hashtable_rehashing:0
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0

# Persistence
loading:0
async_loading:0
current_cow_peak: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:1740449530
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_saves:0
rdb_last_cow_size:0
rdb_last_load_keys_expired:0
rdb_last_load_keys_loaded: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_rewrites:0
aof_rewrites_consecutive_failures:0
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:2
total_commands_processed:4
instantaneous_ops_per_sec:0
total_net_input_bytes:121
total_net_output_bytes:72
total_net_repl_input_bytes:0
total_net_repl_output_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
instantaneous_input_repl_kbps:0.00
instantaneous_output_repl_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:1
evicted_keys:0
evicted_clients:0
evicted_scripts:0
total_eviction_exceeded_time:0
current_eviction_exceeded_time:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
pubsubshard_channels: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
total_active_defrag_time:0
current_active_defrag_time:0
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:1
dump_payload_sanitizations:0
total_reads_processed:6
total_writes_processed:4
io_threaded_reads_processed:0
io_threaded_writes_processed:0
io_threaded_freed_objects:0
io_threaded_poll_processed:0
io_threaded_total_prefetch_batches:0
io_threaded_total_prefetch_entries:0
client_query_buffer_limit_disconnections:0
client_output_buffer_limit_disconnections:0
reply_buffer_shrinks:1
reply_buffer_expands:0
eventloop_cycles:963
eventloop_duration_sum:184386
eventloop_duration_cmd_sum:1182
instantaneous_eventloop_cycles_per_sec:9
instantaneous_eventloop_duration_usec:173
acl_access_denied_auth:0
acl_access_denied_cmd:0
acl_access_denied_key:0
acl_access_denied_channel:0

# Replication
role:master
connected_slaves:0
replicas_waiting_psync:0
master_failover_state:no-failover
master_replid:1d1c0bbdb37dc73d23a599c88b0c5281953f65b2
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:10485760
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:0.078904
used_cpu_user:0.141944
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
used_cpu_sys_main_thread:0.078716
used_cpu_user_main_thread:0.141606

# Modules
module:name=seqList,ver=1,api=1,filters=0,usedby=[],using=[],options=[]
module:name=exstrings,ver=1,api=1,filters=0,usedby=[],using=[],options=[]

# Commandstats
cmdstat_command|docs:calls=1,usec=1156,usec_per_call=1156.00,rejected_calls=0,failed_calls=0
cmdstat_keys:calls=1,usec=4,usec_per_call=4.00,rejected_calls=0,failed_calls=0
cmdstat_cy.test:calls=1,usec=13,usec_per_call=13.00,rejected_calls=0,failed_calls=0
cmdstat_set:calls=1,usec=9,usec_per_call=9.00,rejected_calls=0,failed_calls=0

# Errorstats
errorstat_ERR:count=1

# Latencystats
latency_percentiles_usec_command|docs:p50=1163.263,p99=1163.263,p99.9=1163.263
latency_percentiles_usec_keys:p50=4.015,p99=4.015,p99.9=4.015
latency_percentiles_usec_cy.test:p50=13.055,p99=13.055,p99.9=13.055
latency_percentiles_usec_set:p50=9.023,p99=9.023,p99.9=9.023

# Cluster
cluster_enabled:0

# Keyspace

------ CLIENT LIST OUTPUT ------
id=5 addr=127.0.0.1:43544 laddr=127.0.0.1:6379 fd=10 name=*redacted* age=0 idle=0 flags=N db=0 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=11 multi-mem=0 rbs=16384 rbp=16384 obl=16384 oll=10 omem=205040 tot-mem=222347 events=r cmd=command|docs user=*redacted* redir=-1 resp=2 lib-name= lib-ver= tot-net-in=27 tot-net-out=0 tot-cmds=1

------ CURRENT CLIENT INFO ------
id=5 addr=127.0.0.1:43544 laddr=127.0.0.1:6379 fd=10 name=*redacted* age=0 idle=0 flags=N db=0 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=11 multi-mem=0 rbs=16384 rbp=16384 obl=16384 oll=10 omem=205040 tot-mem=222347 events=r cmd=command|docs user=*redacted* redir=-1 resp=2 lib-name= lib-ver= tot-net-in=27 tot-net-out=0 tot-cmds=1
argc: '2'
26099:signal-handler (1740449626) Crashed running signal handler. Providing reduced version of recursive crash report.
26099:M 25 Feb 2025 02:13:46.807 # valkey 8.0.2 crashed by signal: 11, si_code: 1
26099:M 25 Feb 2025 02:13:46.807 # Accessing address: 0xffffffffffffffff
26099:M 25 Feb 2025 02:13:46.807 # Crashed running the instruction at: 0x505974

------ STACK TRACE ------
EIP:
./src/valkey-server 127.0.0.1:6379(logCurrentClient+0x144)[0x505974]

Backtrace:
/lib64/libc.so.6(+0x40cf0)[0x7f05aa875cf0]
./src/valkey-server 127.0.0.1:6379(logCurrentClient+0x144)[0x505974]
./src/valkey-server 127.0.0.1:6379(printCrashReport+0x29)[0x505d39]
./src/valkey-server 127.0.0.1:6379[0x50979d]
/lib64/libc.so.6(+0x40cf0)[0x7f05aa875cf0]
./src/valkey-server 127.0.0.1:6379(logCurrentClient+0x144)[0x505974]
./src/valkey-server 127.0.0.1:6379(printCrashReport+0x29)[0x505d39]
./src/valkey-server 127.0.0.1:6379(_serverPanic+0x236)[0x506446]
./src/valkey-server 127.0.0.1:6379[0x48e49a]
./src/valkey-server 127.0.0.1:6379[0x49bdcc]
./src/valkey-server 127.0.0.1:6379(processInputBuffer+0x15b)[0x4935ab]
./src/valkey-server 127.0.0.1:6379(readQueryFromClient+0xa0)[0x493770]
./src/valkey-server 127.0.0.1:6379[0x5b38ba]
./src/valkey-server 127.0.0.1:6379(aeMain+0x8a)[0x45ecea]
./src/valkey-server 127.0.0.1:6379(main+0x4b4)[0x454054]
/lib64/libc.so.6(+0x2a088)[0x7f05aa85f088]
/lib64/libc.so.6(__libc_start_main+0x8b)[0x7f05aa85f14b]
./src/valkey-server 127.0.0.1:6379(_start+0x25)[0x4546b5]

------ STACK TRACE DONE ------

------ REGISTERS ------
26099:M 25 Feb 2025 02:13:46.809 #
RAX:00007f05aa29e140 RBX:0000000000000000
RCX:0000000000000400 RDX:0000000000000002
RDI:00007f05aa29e140 RSI:0000000000000000
RBP:00007ffe4469c700 RSP:00007ffe4469c6c0
R8 :0000000000000002 R9 :00000000ffffffff
R10:0000000000000000 R11:0000000000000246
R12:00007f05aa29e140 R13:0000000000505974
R14:00007f05aa398a80 R15:0000000000000000
RIP:0000000000505974 EFL:0000000000010202
CSGSFS:002b000000000033
26099:M 25 Feb 2025 02:13:46.809 * hide-user-data-from-log is on, skip logging stack content to avoid spilling user data.

------ DUMPING CODE AROUND EIP ------
Symbol: logCurrentClient (base: 0x505830)
Module: ./src/valkey-server 127.0.0.1:6379 (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x505830 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
26099:M 25 Feb 2025 02:13:46.809 # dump of function (hexdump of 452 bytes):
4885ff0f84e7030000554889e5415741564989fe41554154534883ec18833d142b2800030f8e460300008b1d0c2b2800e82b4bf7ff4c89f689da4889c7e8ce9ef8ff833def2a2800034889c30f8efe0200004889dfe89656f7ff833dd72a2800030f8ec9020000418b565885d20f8ede01000031dbe9a4000000660f1f4400003c010f84780100003c020f845001000041c0ed03450fb6ed0f1f84000000000031f6bfa70b6a00e8a48e0c004c89ea4c89fe4889c7e896b9f7ff833d772a2800034989c50f8ebe0000004d8b7c2408bec3536a004c89ffe8b40af4ff85c00f8454010000bea0d569004c89ffe89f0af4ff85c00f843f0100004d85ed74084c89efe88a54f7ff4c89e7e8e246f9ff418b46584883c30139d80f8e2e0100008b05182a2800895dcc85c074054885db7578498b4660488b3cd8e8b34cf9ff4c8b78084989c4450fb66fff4489e883e0073c030f84c900000041f6c5040f841fffffff4531ed3c040f8534ffffff4d8b6fefb8800000004939c54c0f47e8e91fffffff0f1f80000000008b55cc4889c1be9b276a00bf0304000031c0e8616c0c00e926ffffff0f1f4000833d89292800030f8f59ffffff498b4660488b04d8488b50080fb64a

=== VALKEY BUG REPORT END. Make sure to include from START to END. ===

       Please report the crash by opening an issue on github:

           https://github.com/valkey-io/valkey/issues

  If a module was involved, please open in the module's repo instead.

  Suspect RAM error? Use valkey-server --test-memory to verify it.

  Some other issues could be detected by valkey-server --check-system
Segmentation fault (core dumped)

Additional information

1. Try to close key twice by invoking ValkeyModule_CloseKey() twice. It is an attempt.

int Test_RedisCommand(RedisModuleCtx* ctx, RedisModuleString** argv, int argc)
{
    RedisModule_AutoMemory(ctx);
    RedisModuleString* key1Name;
    RedisModuleString* key2Name;
    RedisModuleKey* key1;
    RedisModuleKey* key2;

    if (argc == 2)
    {
        key1Name = argv[1];

        key1 = RedisModule_OpenKey(ctx, key1Name, REDISMODULE_WRITE);
 
        RedisModule_UnlinkKey(key1);

        RedisModule_CloseKey(key1);
        RedisModule_CloseKey(key1);
        return RedisModule_ReplyWithSimpleString(ctx, "OK");
    }
    else if (argc == 3)
    {
        key1Name = argv[1];
        key2Name = argv[2];
        key1 = RedisModule_OpenKey(ctx, key1Name, REDISMODULE_WRITE);
        key2 = RedisModule_OpenKey(ctx, key2Name, REDISMODULE_WRITE);
 
        RedisModule_UnlinkKey(key1);
        RedisModule_UnlinkKey(key2);

        RedisModule_CloseKey(key1);
        RedisModule_CloseKey(key2);
        RedisModule_CloseKey(key2);
        return RedisModule_ReplyWithSimpleString(ctx, "OK");
    }
    return RedisModule_ReplyWithSimpleString(ctx, "NOK");

}

    if (RedisModule_CreateCommand(ctx, "cy.test",
                                  Test_RedisCommand, "write deny-oom", 0, 0, 0) == REDISMODULE_ERR)

2. execute command

127.0.0.1:6379> set a aa
OK
127.0.0.1:6379> cy.test a
OK
127.0.0.1:6379> keys *
(error) ERR unknown command '*', with args beginning with: '*'
127.0.0.1:6379> exit
(svnenv)root@c5c0b8b4b2f9:/trunk/chenyan/valkey-8.0.2$ ./src/valkey-cli
127.0.0.1:6379> keys *
Could not connect to Valkey at 127.0.0.1:6379: Connection refused
not connected> keys *
(empty array)
127.0.0.1:6379> set a aa
OK
127.0.0.1:6379> cy.test a
OK
127.0.0.1:6379> keys *
(error) ERR unknown command '*', with args beginning with: '*'
127.0.0.1:6379> exit
(svnenv)root@c5c0b8b4b2f9:/trunk/chenyan/valkey-8.0.2$ ./src/valkey-cli
127.0.0.1:6379> set a aa
Could not connect to Valkey at 127.0.0.1:6379: Connection refused


3. valkey sever crashed at

=== VALKEY BUG REPORT START: Cut & paste starting from here ===
26099:M 25 Feb 2025 02:13:46.791 # ------------------------------------------------
26099:M 25 Feb 2025 02:13:46.791 # !!! Software Failure. Press left mouse button to continue
26099:M 25 Feb 2025 02:13:46.791 # Guru Meditation: decrRefCount against refcount <= 0 #object.c:396

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

26102 bio_lazy_free
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26101 bio_aof
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26100 bio_close_file
/lib64/libc.so.6(+0x93da9)[0x7f05aa8c8da9]
/lib64/libc.so.6(pthread_cond_wait+0x229)[0x7f05aa8cb7b9]
./src/valkey-server 127.0.0.1:6379(bioProcessBackgroundJobs+0x18e)[0x53225e]
/lib64/libc.so.6(+0x97697)[0x7f05aa8cc697]
/lib64/libc.so.6(+0x11b50c)[0x7f05aa95050c]

26099 valkey-server *
./src/valkey-server 127.0.0.1:6379[0x48e49a]
./src/valkey-server 127.0.0.1:6379[0x49bdcc]
./src/valkey-server 127.0.0.1:6379(processInputBuffer+0x15b)[0x4935ab]
./src/valkey-server 127.0.0.1:6379(readQueryFromClient+0xa0)[0x493770]
./src/valkey-server 127.0.0.1:6379[0x5b38ba]
./src/valkey-server 127.0.0.1:6379(aeMain+0x8a)[0x45ecea]
./src/valkey-server 127.0.0.1:6379(main+0x4b4)[0x454054]
/lib64/libc.so.6(+0x2a088)[0x7f05aa85f088]
/lib64/libc.so.6(__libc_start_main+0x8b)[0x7f05aa85f14b]
./src/valkey-server 127.0.0.1:6379(_start+0x25)[0x4546b5]

4/4 expected stacktraces.
@zh1029
Copy link
Author

zh1029 commented Feb 25, 2025

The RC is invoking ValkeyModule_CloseKey() twice. But I think valkey shall be robust to avoid crashing in this situation.

@sungming2
Copy link
Contributor

I can take a look

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sungming2 sungming2

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@zh1029 @sungming2