Starting Advanced key-value store...
491342:C 10 Jun 2022 16:34:41.506 * Supervised by systemd. Please make sure you set appropriate values for TimeoutStartSec and TimeoutStopSec in your service unit.
491342:C 10 Jun 2022 16:34:41.507 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
491342:C 10 Jun 2022 16:34:41.507 # Redis version=7.0.1, bits=64, commit=00000000, modified=0, pid=491342, just started
491342:C 10 Jun 2022 16:34:41.507 # Configuration loaded
491342:M 10 Jun 2022 16:34:41.507 * monotonic clock: POSIX clock_gettime
491342:M 10 Jun 2022 16:34:41.508 * Running mode=standalone, port=6379.
491342:M 10 Jun 2022 16:34:41.508 # Server initialized
[50B blob data]
=== REDIS BUG REPORT START: Cut & paste starting from here ===
491342:M 10 Jun 2022 16:34:41.508 # Redis 7.0.1 crashed by signal: 11, si_code: 1
491342:M 10 Jun 2022 16:34:41.508 # Accessing address: 0x129c8
491342:M 10 Jun 2022 16:34:41.508 # Crashed running the instruction at: 0x7f237834d668
------ STACK TRACE ------
EIP:
/usr/lib/libjemalloc.so.2(malloc_usable_size+0xa8)[0x7f237834d668]
Backtrace:
/usr/lib/libc.so.6(+0x3e8e0)[0x7f2377c1f8e0]
/usr/lib/libjemalloc.so.2(malloc_usable_size+0xa8)[0x7f237834d668]
/usr/bin/redis-server 127.0.0.1:6379(sdsfree+0x21)[0x55a179a4d1b1]
/usr/bin/redis-server 127.0.0.1:6379(linuxMemoryWarnings+0x79)[0x55a179a41669]
/usr/bin/redis-server 127.0.0.1:6379(main+0x2ad)[0x55a179a333ad]
/usr/lib/libc.so.6(+0x29290)[0x7f2377c0a290]
/usr/lib/libc.so.6(__libc_start_main+0x8a)[0x7f2377c0a34a]
/usr/bin/redis-server 127.0.0.1:6379(_start+0x25)[0x55a179a33a25]
------ REGISTERS ------
491342:M 10 Jun 2022 16:34:41.509 #
RAX:00000000000129c8 RBX:00000000000129c8
RCX:00007ffc42539a47 RDX:00007f2377712968
RDI:00007f23777127b8 RSI:00007f23783c44e8
RBP:00007ffc42539a48 RSP:00007ffc425396c0
R8 :0000000000000001 R9 :0000000000000000
R10:0000000000000000 R11:0000000000000246
R12:00007ffc42539a48 R13:0000000000000000
R14:00007f2377712968 R15:00007ffc42539a68
RIP:00007f237834d668 EFL:0000000000010206
CSGSFS:002b000000000033
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396cf) -> 00007f2377c65b06
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396ce) -> 0000000000000008
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396cd) -> 00007f237723c200
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396cc) -> 009fd62f67238b00
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396cb) -> 00007f23777127b8
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396ca) -> 00007f23777127c0
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c9) -> 00007f2378352ff1
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c8) -> 00000000000001b6
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c7) -> 0000000000000000
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c6) -> 0000000000000000
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c5) -> b39fd62f67238b00
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c4) -> 0000000000000000
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c3) -> 00007f23774010c0
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c2) -> 0000000000000024
491342:M 10 Jun 2022 16:34:41.510 # (00007ffc425396c1) -> 0000000000005000
491342:M 10 Jun 2022 16:34:41.511 # (00007ffc425396c0) -> 0000000000000040
------ INFO OUTPUT ------
# Server
redis_version:7.0.1
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:4eba5fc3ec3dea2f
redis_mode:standalone
os:Linux 5.18.0-pf1 x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
atomicvar_api:c11-builtin
gcc_version:12.1.0
process_id:491342
process_supervised:systemd
run_id:f5c9da2b202336e58c4ebecc2e40fe04a6abcd50
tcp_port:6379
server_time_usec:1654871681501872
uptime_in_seconds:0
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:10704513
executable:/usr/bin/redis-server
config_file:/etc/redis/redis.conf
io_threads_active:0
# Clients
connected_clients:0
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
# Memory
used_memory:878432
used_memory_human:857.84K
used_memory_rss:0
used_memory_rss_human:0B
used_memory_peak:878432
used_memory_peak_human:857.84K
used_memory_peak_perc:inf%
used_memory_overhead:200
used_memory_startup:0
used_memory_dataset:878232
used_memory_dataset_perc:99.98%
allocator_allocated:0
allocator_active:0
allocator_resident:0
total_system_memory:2075303936
total_system_memory_human:1.93G
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:32768
used_memory_vm_total:64512
used_memory_vm_total_human:63.00K
used_memory_functions:200
used_memory_scripts:200
used_memory_scripts_human:200B
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:-nan
allocator_frag_bytes:0
allocator_rss_ratio:-nan
allocator_rss_bytes:0
rss_overhead_ratio:-nan
rss_overhead_bytes:0
mem_fragmentation_ratio:-nan
mem_fragmentation_bytes:0
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
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:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1654871681
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:0
total_commands_processed:0
instantaneous_ops_per_sec:0
total_net_input_bytes:0
total_net_output_bytes:0
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:0
evicted_keys:0
evicted_clients:0
total_eviction_exceeded_time:0
current_eviction_exceeded_time:0
keyspace_hits:0
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
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:0
dump_payload_sanitizations:0
total_reads_processed:0
total_writes_processed:0
io_threaded_reads_processed:0
io_threaded_writes_processed:0
reply_buffer_shrinks:0
reply_buffer_expands:0
# Replication
role:master
connected_slaves:0
master_failover_state:no-failover
master_replid:175542c754b2fa0bfcd03259385f11680d8c6185
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.009845
used_cpu_user:0.036064
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000575
used_cpu_sys_main_thread:0.009845
used_cpu_user_main_thread:0.036064
# Modules
# Commandstats
# Errorstats
# Latencystats
# Cluster
cluster_enabled:0
# Keyspace
------ CLIENT LIST OUTPUT ------
------ MODULES INFO OUTPUT ------
------ CONFIG DEBUG OUTPUT ------
io-threads 1
repl-diskless-load disabled
lazyfree-lazy-user-del no
repl-diskless-sync yes
io-threads-do-reads no
lazyfree-lazy-server-del no
replica-read-only yes
activedefrag no
lazyfree-lazy-user-flush no
lazyfree-lazy-expire no
proto-max-bulk-len 512mb
slave-read-only yes
client-query-buffer-limit 1gb
list-compress-depth 0
lazyfree-lazy-eviction no
sanitize-dump-payload no
------ FAST MEMORY TEST ------
*** Preparing to test memory region 55a179c5c000 (122880 bytes)
*** Preparing to test memory region 7f2376e00000 (6275072 bytes)
*** Preparing to test memory region 7f2377400000 (2097152 bytes)
*** Preparing to test memory region 7f2377710000 (28672 bytes)
*** Preparing to test memory region 7f2377809000 (8192 bytes)
*** Preparing to test memory region 7f237797d000 (4096 bytes)
*** Preparing to test memory region 7f2377bde000 (12288 bytes)
*** Preparing to test memory region 7f2377de0000 (61440 bytes)
*** Preparing to test memory region 7f23780cc000 (16384 bytes)
*** Preparing to test memory region 7f2378244000 (4096 bytes)
*** Preparing to test memory region 7f23783bd000 (2138112 bytes)
*** Preparing to test memory region 7f23785d3000 (8192 bytes)
.O.O.O.O.O.O.O.O.O.O.O.O
Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.
------ DUMPING CODE AROUND EIP ------
Symbol: malloc_usable_size (base: 0x7f237834d5c0)
Module: /usr/lib/libjemalloc.so.2 (base 0x7f237832c000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x7f237834d5c0 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
491342:M 10 Jun 2022 16:34:41.557 # dump of function (hexdump of 296 bytes):
f30f1efa4156534881ec880100004889fb64488b0425280000004889842480010000488d05279127008038007437488b05e3e706006480b830030000000f85df0000004885db0f849300000064488b042500000000480305bce706004c8db0b0010000eb134885db74754989e64c89f767e8ea9c040031c04889d948c1e91e83e10f4889da4881e2000000c048c1e104498b3c0e4839d7754b48c1eb0981e3f8ff1f0049035c0e08488b0348c1e830488d0d8a8627004c8b34c164488b042528000000483b8424800100000f85fb0000004c89f04881c4880100005b415ec34531f6ebd6498d340e493996000100007563498b86080100004989be00010000498b7c0e084989be080100004889164989440e0848c1eb0981e3f8ff1f004801c3eb8664488b3c2500
=== REDIS BUG REPORT END. Make sure to include from START to END. ===
Please report the crash by opening an issue on github:
http://github.com/redis/redis/issues
If a Redis module was involved, please open in the module's repo instead.
Suspect RAM error? Use redis-server --test-memory to verify it.
Some other issues could be detected by redis-server --check-system
redis.service: Main process exited, code=dumped, status=11/SEGV
redis.service: Failed with result 'core-dump'.
Failed to start Advanced key-value store.
Additional information
- OS distribution and version
Arch Linux.
- Steps to reproduce (if any)
Upgraded redis from 7.0.0 to 7.0.1. Downgrading back to 7.0.0 solves the issue.
Comment From: oranagra
looks like a regression from #10636
could it be that /proc/sys/vm/overcommit_memory is inaccessible?
Comment From: pfactum
Yes, it is inaccessible. I run redis in a restricted mode with ProcSubset=pid set. Once I lift up this restriction, it starts fine, so thanks for the pointer.
But in any case, regardless of the file accessibility, it shouldn't perhaps crash?
Comment From: oranagra
yeah, of course.. just trying to make sure the bug i see is the same one that you run into.
Comment From: pfactum
Yeah, I see. checkOvercommit() returns -1 without allocating error_msg, and then in linuxMemoryWarnings() it is being free()'ed by sdsfree(). Right?
Comment From: enjoy-binbin
Yeah, I see. checkOvercommit() returns -1 without allocating error_msg, and then in linuxMemoryWarnings() it is being free()'ed by sdsfree(). Right?
thanks for the report, yes (actually it was crash in serverLog(LL_WARNING,"WARNING %s", err_msg); not the sdsfree), i think we should return 0 in this case, also the log had two warning which i think it is odd (after patch #10841)
# WARNING 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.