Redis server crashes in cluster mode, right after startup. Environment: Linux dockerhost 4.12.14-197.75-default #1 SMP Tue Dec 1 12:18:41 UTC 2020 (b3ff9f6) x86_64 x86_64 x86_64 GNU/Linux Red Hat Enterprise Linux Server release 7.6 (Maipo) + jemalloc 5.2.0
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.
197:C 08 Nov 2021 21:31:34.942 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
197:C 08 Nov 2021 21:31:34.942 # Redis version=6.2.6, bits=64, commit=223653de, modified=1, pid=197, just started
197:C 08 Nov 2021 21:31:34.942 # Configuration loaded
197:M 08 Nov 2021 21:31:34.943 * monotonic clock: POSIX clock_gettime
197:M 08 Nov 2021 21:31:34.943 * No cluster configuration found, I'm 929fff492391d88e40652d7ca63d5f5dace17e3b
197:M 08 Nov 2021 21:31:34.945 * Running mode=cluster, port=7001.
197:M 08 Nov 2021 21:31:34.945 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
197:M 08 Nov 2021 21:31:34.945 # Server initialized
197:M 08 Nov 2021 21:31:34.945 # 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.
197:M 08 Nov 2021 21:31:34.947 * Ready to accept connections
197:M 08 Nov 2021 21:31:37.975 # configEpoch set to 2 via CLUSTER SET-CONFIG-EPOCH
197:M 08 Nov 2021 21:31:38.156 # IP address for this node updated to 127.0.0.1
197:M 08 Nov 2021 21:31:39.983 * Replica 127.0.0.1:7006 asks for synchronization
197:M 08 Nov 2021 21:31:39.983 * Partial resynchronization not accepted: Replication ID mismatch (Replica asked for 'c56979f2c70327e86f324e66956e8c8cb3bba6f3', my replication IDs are '718f91019823dbda847f9194523c52503a158f82' and '0000000000000000000000000000000000000000')
197:M 08 Nov 2021 21:31:39.983 * Replication backlog created, my new replication IDs are '546ab2375de323eaeeb228f4a83130e4870d4ccb' and '0000000000000000000000000000000000000000'
197:M 08 Nov 2021 21:31:39.983 * Starting BGSAVE for SYNC with target: disk
197:M 08 Nov 2021 21:31:39.986 * Background saving started by pid 249
249:C 08 Nov 2021 21:31:39.988 * DB saved on disk
197:M 08 Nov 2021 21:31:39.988 * Replica 127.0.0.1:7008 asks for synchronization
197:M 08 Nov 2021 21:31:39.988 * Partial resynchronization not accepted: Replication ID mismatch (Replica asked for 'd5d2a13d4b0d4f301d79f0c9f85eb6979b7561e8', my replication IDs are '546ab2375de323eaeeb228f4a83130e4870d4ccb' and '0000000000000000000000000000000000000000')
197:M 08 Nov 2021 21:31:39.988 * Waiting for end of BGSAVE for SYNC
249:C 08 Nov 2021 21:31:39.988 * RDB: 8 MB of memory used by copy-on-write
197:M 08 Nov 2021 21:31:40.065 * Background saving terminated with success
197:M 08 Nov 2021 21:31:40.065 * Synchronization with replica 127.0.0.1:7006 succeeded
197:M 08 Nov 2021 21:31:40.065 * Synchronization with replica 127.0.0.1:7008 succeeded
197:M 08 Nov 2021 21:31:42.974 # Cluster state changed: ok
197:M 08 Nov 2021 21:31:49.208 * DB saved on disk
197:M 08 Nov 2021 21:31:49.320 * DB saved on disk
197:M 08 Nov 2021 21:32:07.440 * DB saved on disk
197:M 08 Nov 2021 21:32:07.547 * DB saved on disk
197:M 08 Nov 2021 21:32:07.658 * DB saved on disk
197:M 08 Nov 2021 21:32:07.756 * DB saved on disk
197:M 08 Nov 2021 21:32:07.856 * DB saved on disk
197:M 08 Nov 2021 21:32:07.959 * DB saved on disk
197:M 08 Nov 2021 21:32:10.058 # New configEpoch set to 10
197:M 08 Nov 2021 21:32:10.058 # configEpoch updated after importing slot 0
=== REDIS BUG REPORT START: Cut & paste starting from here ===
197:M 08 Nov 2021 21:32:17.340 # Redis 6.2.6 crashed by signal: 11, si_code: 1
197:M 08 Nov 2021 21:32:17.340 # Accessing address: 0xffffffffffffffff
197:M 08 Nov 2021 21:32:17.340 # Crashed running the instruction at: 0x4886f0
------ STACK TRACE ------
EIP:
redis-server *:7001 [cluster](debugCommand+0x180)[0x4886f0]
Backtrace:
/usr/lib64/libpthread.so.0(+0xf5d0)[0x7f3e0f07a5d0]
redis-server *:7001 [cluster](debugCommand+0x180)[0x4886f0]
redis-server *:7001 [cluster](call+0x9d)[0x43906d]
redis-server *:7001 [cluster](processCommand+0x554)[0x43ab24]
redis-server *:7001 [cluster](processCommandAndResetClient+0x1c)[0x44dcbc]
redis-server *:7001 [cluster](processInputBuffer+0xda)[0x45029a]
redis-server *:7001 [cluster][0x4db7b8]
redis-server *:7001 [cluster](aeProcessEvents+0x2a1)[0x4323b1]
redis-server *:7001 [cluster](aeMain+0x1d)[0x43260d]
redis-server *:7001 [cluster](main+0x309)[0x42ee19]
/usr/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f3e0ecc0495]
redis-server *:7001 [cluster][0x42f2d9]
------ REGISTERS ------
197:M 08 Nov 2021 21:32:17.353 #
RAX:0000000000000000 RBX:00007f3e0c1b4a53
RCX:0000000000000010 RDX:0000000000000010
RDI:00007f3e0c1b4a50 RSI:0000000000581430
RBP:00007f3e0c2e44c0 RSP:00007ffc0c16d800
R8 :0000000000000000 R9 :0000000000000009
R10:fffffffffffffa69 R11:001b9c2c42219c9f
R12:0000000000000002 R13:00007f3e0e87be90
R14:000008991b905d56 R15:00000000007dea70
RIP:00000000004886f0 EFL:0000000000010246
CSGSFS:0000000000000033
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d80f) -> 0000000000000000
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d80e) -> 0000000000000000
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d80d) -> 0000000000000000
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d80c) -> 6663333037666633
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d80b) -> 3066336633653539
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d80a) -> 6165343765396361
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d809) -> 3066346239656339
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d808) -> 3462353338646138
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d807) -> 2e0b000000000000
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d806) -> 0100000000000000
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d805) -> 0a00000000000000
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d804) -> 030001005d1b0100
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d803) -> 00000000004920f0
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d802) -> 0000000000000000
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d801) -> ffffffffffffffff
197:M 08 Nov 2021 21:32:17.353 # (00007ffc0c16d800) -> 00007f3e0e81b690
------ INFO OUTPUT ------
# Server
redis_version:6.2.6
redis_git_sha1:223653de
redis_git_dirty:1
redis_build_id:6173588f3a49851f
redis_mode:cluster
os:Linux 3.10.0-957.el7.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:c11-builtin
gcc_version:8.3.1
process_id:197
process_supervised:no
run_id:72991bb5706a4a64eea211e68e2c686ab29734db
tcp_port:7001
server_time_usec:1636403537340558
uptime_in_seconds:43
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:9013585
executable:/workspace/cnp_layer/test/framework/redis/63036/7001/redis-server
config_file:/workspace/cnp_layer/test/framework/redis/63036/7001/redis.conf
io_threads_active:0
# Clients
connected_clients:3
cluster_connections:16
maxclients:10000
client_recent_max_input_buffer:40
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
# Memory
used_memory:2801040
used_memory_human:2.67M
used_memory_rss:13299712
used_memory_rss_human:12.68M
used_memory_peak:2902744
used_memory_peak_human:2.77M
used_memory_peak_perc:96.50%
used_memory_overhead:2600064
used_memory_startup:1468408
used_memory_dataset:200976
used_memory_dataset_perc:15.08%
allocator_allocated:2911544
allocator_active:3297280
allocator_resident:8241152
total_system_memory:134893707264
total_system_memory_human:125.63G
used_memory_lua:35840
used_memory_lua_human:35.00K
used_memory_scripts:648
used_memory_scripts_human:648B
number_of_cached_scripts:3
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.13
allocator_frag_bytes:385736
allocator_rss_ratio:2.50
allocator_rss_bytes:4943872
rss_overhead_ratio:1.61
rss_overhead_bytes:5058560
mem_fragmentation_ratio:4.79
mem_fragmentation_bytes:10521496
mem_not_counted_for_evict:378
mem_replication_backlog:1048576
mem_clients_slaves:41024
mem_clients_normal:41024
mem_aof_buffer:384
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0
# 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:153
rdb_bgsave_in_progress:0
rdb_last_save_time:1636403527
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:1
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:8613888
aof_enabled:1
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
aof_current_size:4650
aof_base_size:0
aof_pending_rewrite:0
aof_buffer_length:0
aof_rewrite_buffer_length:0
aof_pending_bio_fsync:0
aof_delayed_fsync:0
# Stats
total_connections_received:69
total_commands_processed:731
instantaneous_ops_per_sec:31
total_net_input_bytes:105148
total_net_output_bytes:30311
instantaneous_input_kbps:0.84
instantaneous_output_kbps:1.24
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:69
keyspace_misses:4
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:2194
total_forks:1
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:6
dump_payload_sanitizations:0
total_reads_processed:804
total_writes_processed:964
io_threaded_reads_processed:0
io_threaded_writes_processed:0
# Replication
role:master
connected_slaves:2
slave0:ip=127.0.0.1,port=7006,state=online,offset=4596,lag=0
slave1:ip=127.0.0.1,port=7008,state=online,offset=4596,lag=0
master_failover_state:no-failover
master_replid:546ab2375de323eaeeb228f4a83130e4870d4ccb
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:4706
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:1
repl_backlog_histlen:4706
# CPU
used_cpu_sys:0.115639
used_cpu_user:0.089572
used_cpu_sys_children:0.003610
used_cpu_user_children:0.000902
used_cpu_sys_main_thread:0.112233
used_cpu_user_main_thread:0.089157
# Modules
# Commandstats
cmdstat_cluster:calls=413,usec=10057,usec_per_call=24.35,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=2,usec=2,usec_per_call=1.00,rejected_calls=0,failed_calls=0
cmdstat_hset:calls=1,usec=36,usec_per_call=36.00,rejected_calls=0,failed_calls=0
cmdstat_del:calls=63,usec=235,usec_per_call=3.73,rejected_calls=1,failed_calls=0
cmdstat_hmget:calls=1,usec=2,usec_per_call=2.00,rejected_calls=3,failed_calls=0
cmdstat_psync:calls=2,usec=3479,usec_per_call=1739.50,rejected_calls=0,failed_calls=0
cmdstat_hget:calls=2,usec=8,usec_per_call=4.00,rejected_calls=0,failed_calls=0
cmdstat_replconf:calls=78,usec=63,usec_per_call=0.81,rejected_calls=0,failed_calls=0
cmdstat_hdel:calls=2,usec=19,usec_per_call=9.50,rejected_calls=0,failed_calls=0
cmdstat_hvals:calls=1,usec=3,usec_per_call=3.00,rejected_calls=0,failed_calls=0
cmdstat_set:calls=62,usec=338,usec_per_call=5.45,rejected_calls=1,failed_calls=0
cmdstat_smembers:calls=3,usec=32,usec_per_call=10.67,rejected_calls=0,failed_calls=0
cmdstat_hmset:calls=3,usec=19,usec_per_call=6.33,rejected_calls=0,failed_calls=0
cmdstat_select:calls=1,usec=0,usec_per_call=0.00,rejected_calls=0,failed_calls=0
cmdstat_restore-asking:calls=1,usec=9,usec_per_call=9.00,rejected_calls=0,failed_calls=0
cmdstat_get:calls=63,usec=128,usec_per_call=2.03,rejected_calls=1,failed_calls=0
cmdstat_flushall:calls=8,usec=6177,usec_per_call=772.12,rejected_calls=0,failed_calls=0
cmdstat_script:calls=3,usec=234,usec_per_call=78.00,rejected_calls=0,failed_calls=0
cmdstat_keys:calls=11,usec=18,usec_per_call=1.64,rejected_calls=0,failed_calls=0
cmdstat_hgetall:calls=2,usec=6,usec_per_call=3.00,rejected_calls=0,failed_calls=0
cmdstat_info:calls=2,usec=124,usec_per_call=62.00,rejected_calls=0,failed_calls=0
cmdstat_sadd:calls=7,usec=17,usec_per_call=2.43,rejected_calls=0,failed_calls=0
# Errorstats
errorstat_ERR:count=3
errorstat_MOVED:count=3
# Cluster
cluster_enabled:1
# Keyspace
------ CLIENT LIST OUTPUT ------
id=4 addr=127.0.0.1:49334 laddr=127.0.0.1:7001 fd=29 name= age=38 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=5 addr=127.0.0.1:49338 laddr=127.0.0.1:7001 fd=32 name= age=38 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=68 addr=127.0.0.1:50578 laddr=127.0.0.1:7001 fd=31 name= age=7 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=20520 events=r cmd=restore-asking user=default redir=-1
id=70 addr=127.0.0.1:50600 laddr=127.0.0.1:7001 fd=12 name= age=2 idle=0 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=20504 events=r cmd=del user=default redir=-1
id=71 addr=127.0.0.1:50618 laddr=127.0.0.1:7001 fd=30 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=29 qbuf-free=40925 argv-mem=13 obl=0 oll=0 omem=0 tot-mem=61469 events=r cmd=debug user=default redir=-1
------ CURRENT CLIENT INFO ------
id=71 addr=127.0.0.1:50618 laddr=127.0.0.1:7001 fd=30 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=29 qbuf-free=40925 argv-mem=13 obl=0 oll=0 omem=0 tot-mem=61469 events=r cmd=debug user=default redir=-1
argv[0]: 'debug'
argv[1]: 'segfault'
------ MODULES INFO OUTPUT ------
------ FAST MEMORY TEST ------
197:M 08 Nov 2021 21:32:17.354 # Bio thread for job type #0 terminated
197:M 08 Nov 2021 21:32:17.354 # Bio thread for job type #1 terminated
197:M 08 Nov 2021 21:32:17.354 # Bio thread for job type #2 terminated
*** Preparing to test memory region 7e6000 (2277376 bytes)
*** Preparing to test memory region 1572000 (135168 bytes)
*** Preparing to test memory region 7f3e04000000 (135168 bytes)
*** Preparing to test memory region 7f3e0b600000 (8388608 bytes)
*** Preparing to test memory region 7f3e0be00000 (2097152 bytes)
*** Preparing to test memory region 7f3e0c17c000 (2621440 bytes)
*** Preparing to test memory region 7f3e0c3fd000 (8388608 bytes)
*** Preparing to test memory region 7f3e0cbfe000 (8388608 bytes)
*** Preparing to test memory region 7f3e0d3ff000 (8388608 bytes)
*** Preparing to test memory region 7f3e0dc00000 (8388608 bytes)
*** Preparing to test memory region 7f3e0e400000 (8388608 bytes)
*** Preparing to test memory region 7f3e0f066000 (20480 bytes)
*** Preparing to test memory region 7f3e0f283000 (16384 bytes)
*** Preparing to test memory region 7f3e0fa25000 (4096 bytes)
*** Preparing to test memory region 7f3e0fbaf000 (28672 bytes)
*** Preparing to test memory region 7f3e0fbb8000 (4096 bytes)
.O.O.O.O.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: debugCommand (base: 0x488570)
Module: redis-server *:7001 [cluster] (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x488570 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
197:M 08 Nov 2021 21:32:17.550 # dump of function (hexdump of 512 bytes):
4157415641554154554889fd534881ec281000004c8b6f50448b6748498b4508488b58084183fc020f84b2010000be3a1458004889dfe8d554faff85c00f843d010000bec3cd57004889dfe8c054faff85c00f84cd110000be431458004889dfe8ab54faff85c00f8433010000be4b1458004889dfe89654faff85c00f841e010000bedff558004889dfe88154faff85c00f8421020000be5d1458004889dfe86c54faff85c00f843e130000beab1657004889dfe85754faff85c00f84af010000bef0ea59004889dfe84254faff4183fc03750885c00f8434050000be791458004889dfe82754faff4189c685c00f85ec0100004183fc020f8e67040000418d4424fd4d8d7d10c7442408010000004d8d64c51841bd01000000eb3e0f1f4000be861458004889dfe8e353faff85c00f8473010000be8e1458004889dfe8ce53faff4189c585c00f85d50400004983c7084d39fc0f840e020000498b07be80145800488b58084889dfe8a253faff85c075ae41be04000000ebd3660f1f440000c60425ffffffff784881c4281000005b5d415c415d415e415fc3660f1f44000048c7442420000000004531f64183fc027f6e4889dfbe43145800e85153faff4c89f683f80119ff83e703e8b114fbffbe480158004889efe8a46afcffebaa6690beaa0d57004889dfe82353faff85c00f8539feffff488d7c2420be201b5800b9
=== REDIS BUG REPORT END. Make sure to include from START to END. ===
Additional information
- OS distribution and version
- Steps to reproduce (if any)
Comment From: madolson
Well, you called debug segfault, which causes a segfault. Maybe don't do that. If you didn't do this, you may want to look into verifying no one has gained access to your node and look into hardening your configuration: https://redis.io/topics/security
------ CURRENT CLIENT INFO ------
id=71 addr=127.0.0.1:50618 laddr=127.0.0.1:7001 fd=30 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=29 qbuf-free=40925 argv-mem=13 obl=0 oll=0 omem=0 tot-mem=61469 events=r cmd=debug user=default redir=-1
argv[0]: 'debug'
argv[1]: 'segfault'
Comment From: tp3t3r
Right! My bad, sorry.
Comment From: oranagra
@tp3t3r i see several prints of DB saved on disk and also several calls to CONFIG.
it looks to me like someone is attempting to hack your system, and may have succeeded.
i'd look for the value of config get dir and config get dbfilename, and maybe consider that host compromised.