Crash report
6:M 24 Nov 2020 03:46:25.073 - DB 0: 1266 keys (1266 volatile) in 2048 slots HT.
=== REDIS BUG REPORT START: Cut & paste starting from here ===
6:M 24 Nov 2020 03:46:25.816 # Redis 6.0.4 crashed by signal: 11
6:M 24 Nov 2020 03:46:25.816 # Crashed running the instruction at: 0x4acff8
6:M 24 Nov 2020 03:46:25.816 # Accessing address: 0x6c656401030b
6:M 24 Nov 2020 03:46:25.816 # Failed assertion: <no assertion failed> (<no file>:0)
------ STACK TRACE ------
EIP:
/bin/redis-server 0.0.0.0:7005 [cluster](activeExpireCycle+0x248)[0x4acff8]
Backtrace:
/bin/redis-server 0.0.0.0:7005 [cluster](logStackTrace+0x41)[0x476401]
/bin/redis-server 0.0.0.0:7005 [cluster](sigsegvHandler+0x96)[0x476a86]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7f828bcbb890]
/bin/redis-server 0.0.0.0:7005 [cluster](activeExpireCycle+0x248)[0x4acff8]
/bin/redis-server 0.0.0.0:7005 [cluster](databasesCron+0x10b)[0x4332ab]
/bin/redis-server 0.0.0.0:7005 [cluster](serverCron+0x24a)[0x43614a]
/bin/redis-server 0.0.0.0:7005 [cluster](aeProcessEvents+0x30b)[0x42ec2b]
/bin/redis-server 0.0.0.0:7005 [cluster](aeMain+0x1d)[0x42ef0d]
/bin/redis-server 0.0.0.0:7005 [cluster](main+0x4ed)[0x42b84d]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7f828b8d9b97]
/bin/redis-server 0.0.0.0:7005 [cluster][0x42ba8a]
------ INFO OUTPUT ------
# Server
redis_version:6.0.4
redis_git_sha1:27eef119
redis_git_dirty:1
redis_build_id:a4e2b82597ed8ff0
redis_mode:cluster
os:Linux 3.10.0-1127.el7.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:7.3.1
process_id:6
run_id:752fafa14e2689bc4184d4b809cd07f2d8b15b74
tcp_port:7005
uptime_in_seconds:325832
uptime_in_days:3
hz:10
configured_hz:10
lru_clock:12354065
executable:/bin/redis-server
config_file:/cluster/redis.conf
# Clients
connected_clients:1
client_recent_max_input_buffer:2
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
# Memory
used_memory:2674832
used_memory_human:2.55M
used_memory_rss:6098944
used_memory_rss_human:5.82M
used_memory_peak:18704352
used_memory_peak_human:17.84M
used_memory_peak_perc:14.30%
used_memory_overhead:2552320
used_memory_startup:1464216
used_memory_dataset:122512
used_memory_dataset_perc:10.12%
allocator_allocated:2957560
allocator_active:5447680
allocator_resident:10326016
total_system_memory:2964717568
total_system_memory_human:2.76G
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:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.84
allocator_frag_bytes:2490120
allocator_rss_ratio:1.90
allocator_rss_bytes:4878336
rss_overhead_ratio:0.59
rss_overhead_bytes:-4227072
mem_fragmentation_ratio:2.24
mem_fragmentation_bytes:3380152
mem_not_counted_for_evict:2740
mem_replication_backlog:1048576
mem_clients_slaves:16986
mem_clients_normal:16986
mem_aof_buffer:2740
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0
# Persistence
loading:0
rdb_changes_since_last_save:1980354
rdb_bgsave_in_progress:0
rdb_last_save_time:1606188598
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:339968
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:7708672
module_fork_in_progress:0
module_fork_last_cow_size:0
aof_current_size:61434481
aof_base_size:1924787
aof_pending_rewrite:0
aof_buffer_length:1629
aof_rewrite_buffer_length:0
aof_pending_bio_fsync:0
aof_delayed_fsync:0
# Stats
total_connections_received:22
total_commands_processed:6770297
instantaneous_ops_per_sec:1768
total_net_input_bytes:160803211
total_net_output_bytes:330638216
instantaneous_input_kbps:5.60
instantaneous_output_kbps:267.77
rejected_connections:0
sync_full:1
sync_partial_ok:0
sync_partial_err:1
expired_keys:887050
expired_stale_perc:24.78
expired_time_cap_reached_count:126
expire_cycle_cpu_milliseconds:11725
evicted_keys:0
keyspace_hits:213132
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:14108
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
# Replication
role:master
connected_slaves:1
slave0:ip=192.168.192.130,port=7001,state=online,offset=403621744,lag=0
master_replid:661d07f3a15716c9e314dc122e1d34cb17bc9a41
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:403626662
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:402578087
repl_backlog_histlen:1048576
# CPU
used_cpu_sys:422.630964
used_cpu_user:165.213361
used_cpu_sys_children:1.528267
used_cpu_user_children:0.157220
# Modules
module:name=mw,ver=1,api=1,filters=1,usedby=[],using=[],options=[]
# Commandstats
cmdstat_setex:calls=1270418,usec=9592131,usec_per_call=7.55
cmdstat_persist:calls=11,usec=70,usec_per_call=6.36
cmdstat_mwhgetall:calls=19914,usec=159773,usec_per_call=8.02
cmdstat_incrbyfloat:calls=6,usec=7154,usec_per_call=1192.33
cmdstat_replconf:calls=4950,usec=5087,usec_per_call=1.03
cmdstat_pexpire:calls=11,usec=121,usec_per_call=11.00
cmdstat_incr:calls=11,usec=142,usec_per_call=12.91
cmdstat_incrby:calls=11,usec=144,usec_per_call=13.09
cmdstat_mwdel:calls=153228,usec=2775850,usec_per_call=18.12
cmdstat_exec:calls=454390,usec=10480619,usec_per_call=23.07
cmdstat_pttl:calls=18,usec=46,usec_per_call=2.56
cmdstat_mwhexpire:calls=19914,usec=195186,usec_per_call=9.80
cmdstat_mset:calls=11,usec=823,usec_per_call=74.82
cmdstat_psync:calls=1,usec=534,usec_per_call=534.00
cmdstat_zrevrange:calls=6,usec=55,usec_per_call=9.17
cmdstat_cluster:calls=25,usec=30750,usec_per_call=1230.00
cmdstat_sismember:calls=6,usec=14,usec_per_call=2.33
cmdstat_zrevrangebylex:calls=6,usec=124,usec_per_call=20.67
cmdstat_sscan:calls=6,usec=48,usec_per_call=8.00
cmdstat_smembers:calls=173148,usec=519529,usec_per_call=3.00
cmdstat_get:calls=39828,usec=48230,usec_per_call=1.21
cmdstat_save:calls=4,usec=98548,usec_per_call=24637.00
cmdstat_sadd:calls=1315807,usec=6488610,usec_per_call=4.93
cmdstat_ping:calls=57299,usec=27721,usec_per_call=0.48
cmdstat_msetnx:calls=6,usec=17,usec_per_call=2.83
cmdstat_bitfield:calls=11,usec=9890,usec_per_call=899.09
cmdstat_set:calls=65275,usec=186185,usec_per_call=2.85
cmdstat_zrevrank:calls=6,usec=36,usec_per_call=6.00
cmdstat_mwhsetex:calls=1106760,usec=18755220,usec_per_call=16.95
cmdstat_mwhget:calls=19914,usec=127187,usec_per_call=6.39
cmdstat_setbit:calls=11,usec=731,usec_per_call=66.45
cmdstat_sinter:calls=6,usec=8535,usec_per_call=1422.50
cmdstat_sunion:calls=6,usec=63,usec_per_call=10.50
cmdstat_srem:calls=1091757,usec=3765777,usec_per_call=3.45
cmdstat_ttl:calls=6,usec=15,usec_per_call=2.50
cmdstat_restore-asking:calls=4,usec=318,usec_per_call=79.50
cmdstat_getbit:calls=6,usec=17,usec_per_call=2.83
cmdstat_mget:calls=60,usec=45,usec_per_call=0.75
cmdstat_multi:calls=454390,usec=53642,usec_per_call=0.12
cmdstat_zscan:calls=6,usec=39,usec_per_call=6.50
cmdstat_select:calls=1,usec=1,usec_per_call=1.00
cmdstat_command:calls=6,usec=5628,usec_per_call=938.00
cmdstat_info:calls=2,usec=120,usec_per_call=60.00
cmdstat_expireat:calls=6,usec=66,usec_per_call=11.00
cmdstat_del:calls=446620,usec=2177624,usec_per_call=4.88
cmdstat_sinterstore:calls=11,usec=103849,usec_per_call=9440.82
cmdstat_zadd:calls=33,usec=1528,usec_per_call=46.30
cmdstat_sunionstore:calls=11,usec=219,usec_per_call=19.91
cmdstat_expire:calls=56434,usec=121280,usec_per_call=2.15
cmdstat_mwhdel:calls=19914,usec=249102,usec_per_call=12.51
cmdstat_zrevrangebyscore:calls=6,usec=86,usec_per_call=14.33
# Cluster
cluster_enabled:1
# Keyspace
db0:keys=28,expires=28,avg_ttl=315
------ CLIENT LIST OUTPUT ------
id=642036 addr=192.168.192.130:43896 fd=20 name= age=5003 idle=0 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=1565 oll=0 omem=0 events=r cmd=replconf user=default
id=2786529 addr=192.168.192.130:45836 fd=7 name= age=123 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=4 oll=0 omem=0 events=r cmd=mwhsetex user=default
------ REGISTERS ------
6:M 24 Nov 2020 03:46:25.871 #
RAX:00007f828b5e11cb RBX:00007e0c9301fc3e
RCX:00007f8280000000 RDX:00007f828b600900
RDI:00007f828b402f58 RSI:00006c6564010303
RBP:00006c6564010303 RSP:00007ffdcba4df50
R8 :0000000000000068 R9 :0000000000000012
R10:0000000000000012 R11:0000000000000006
R12:00007e0c93022132 R13:0000000000000008
R14:00000175f85c158d R15:000000000000000b
RIP:00000000004acff8 EFL:0000000000010206
CSGSFS:0000000000000033
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df5f) -> 0000000000000007
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df5e) -> 0000000000000001
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df5d) -> 000000100000000f
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df5c) -> 00000000000061a8
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df5b) -> 0005b4d227b430e3
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df5a) -> 000000000000000a
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df59) -> 0000000000000005
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df58) -> 0000000000000014
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df57) -> 0000000000000014
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df56) -> 0000000100000011
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df55) -> 0000000000000190
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df54) -> 0000000000000014
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df53) -> 000000000000000b
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df52) -> 0000000000000003
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df51) -> 000000000052b1fe
6:M 24 Nov 2020 03:46:25.871 # (00007ffdcba4df50) -> 00007f828b506000
------ MODULES INFO OUTPUT ------
------ FAST MEMORY TEST ------
6:M 24 Nov 2020 03:46:25.884 # Bio thread for job type #0 terminated
6:M 24 Nov 2020 03:46:25.888 # Bio thread for job type #1 terminated
6:M 24 Nov 2020 03:46:25.918 # Bio thread for job type #2 terminated
*** Preparing to test memory region 7c7000 (2277376 bytes)
*** Preparing to test memory region 23a0000 (274432 bytes)
*** Preparing to test memory region 7f8280000000 (135168 bytes)
*** Preparing to test memory region 7f8285a00000 (33554432 bytes)
*** Preparing to test memory region 7f8287c00000 (8388608 bytes)
*** Preparing to test memory region 7f8288400000 (2097152 bytes)
*** Preparing to test memory region 7f82887db000 (2621440 bytes)
*** Preparing to test memory region 7f8288a5c000 (8388608 bytes)
*** Preparing to test memory region 7f828925d000 (8388608 bytes)
*** Preparing to test memory region 7f8289a5e000 (8388608 bytes)
*** Preparing to test memory region 7f828a25f000 (8388608 bytes)
*** Preparing to test memory region 7f828affc000 (16384 bytes)
*** Preparing to test memory region 7f828b000000 (8388608 bytes)
*** Preparing to test memory region 7f828bca5000 (16384 bytes)
*** Preparing to test memory region 7f828bec4000 (16384 bytes)
*** Preparing to test memory region 7f828c88f000 (32768 bytes)
*** Preparing to test memory region 7f828c89b000 (4096 bytes)
.O.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: activeExpireCycle (base: 0x4acdb0)
Module: /bin/redis-server 0.0.0.0:7005 [cluster] (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x4acdb0 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
6:M 24 Nov 2020 03:46:27.587 # dump of function (hexdump of 592 bytes):
4157415641554154555389fb4883ec788b2d62043200e8555bf8ff4889442458e87b9bf9ff85c00f859c0400008d75ffb80a0000004863f64c69c6fa0000004829f048894424504981c0e803000083fb010f84ad0400008b0d5304320083f90f894c246c0f8f7f040000488d44361948633da2fc310031d2c70526f53100000000004869c040420f0048f7f748bac3f5285c8fc2f5288b7c246c48c1e80248f7e24889d0ba0100000048c1e8024885c0480f44c283fb014c0f45c085ff4c894424600f8ea8030000488d44b614c744243000000000c74424680000000048c74424480000000048c74424400000000048894424388b359ef4310031d289f083c601f7f189358ff4310089d0488d14c0488b050afc3100488d04d0488904246690488b04248344243001488b40084c8b70484c0370280f849d030000488b683848036818e8485af8ff4989c54883fd04761a4b8d04b631d2488d048048c1e00248f7f54885c00f8409020000488b4424388b5424304c39f04c0f46f083e20f4f8d3cb64d85f64c89742420895424344a8d0cbd0000000048894c24280f84f70100004885c90f8eee010000488b04244531e44531ff4589e648c7442418000000004d89ec48c7442410000000004d89fd488b48380f1f440000488b04244c89fdc744240c000000004d89ef488b50084c89e04589f44989c6486344240c4883442418014889c74883c00148c1e00548c1e705488b3402488b443a104821ce488b34f04885f674584589e54989eceb1a66904885db7e074901dc4183c5014983c7014885ed4889ee7428488b4608488b6e10
Function at 0x432920 is ustime
Function at 0x446950 is clientsArePaused
Function at 0x432940 is mstime
=== 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/antirez/redis/issues
Suspect RAM error? Use redis-server --test-memory to verify it.
Segmentation fault (core dumped)
Aditional information
(gdb) bt
#0 activeExpireCycle (type=type@entry=0) at expire.c:270
#1 0x0000000000432ae7 in databasesCron () at server.c:1694
#2 0x000000000043597a in serverCron (eventLoop=<optimized out>, id=<optimized out>, clientData=<optimized out>) at server.c:1964
#3 0x000000000042e54b in processTimeEvents (eventLoop=0x7f153160b480) at ae.c:357
#4 aeProcessEvents (eventLoop=eventLoop@entry=0x7f153160b480, flags=flags@entry=27) at ae.c:509
#5 0x000000000042e82d in aeMain (eventLoop=0x7f153160b480) at ae.c:539
#6 0x000000000042b16d in main (argc=<optimized out>, argv=0x7ffc5ba4e428) at server.c:5171
(gdb) bt full
#0 activeExpireCycle (type=type@entry=0) at expire.c:270
e = 0x6c6564010303
idx = <optimized out>
de = 0x6c6564010303
ttl = <optimized out>
table = <optimized out>
slots = <optimized out>
checked_buckets = 88
num = 20
now = 1605771839030
ttl_sum = 138122681626953
ttl_samples = 3
max_buckets = 400
expired = 2
sampled = 5
db = 0x7f1531659000
effort = <optimized out>
config_keys_per_loop = <optimized out>
config_cycle_fast_duration = <optimized out>
config_cycle_slow_time_perc = <optimized out>
config_cycle_acceptable_stale = <optimized out>
current_db = 81994449
timelimit_exit = 0
last_fast_cycle = 1605771838399289
j = <optimized out>
iteration = 25
dbs_per_call = 16
start = 1605771839029054
timelimit = 25000
elapsed = <optimized out>
total_sampled = 131
total_expired = 58
current_perc = <optimized out>
- OS distribution and version centos 7.6
- Steps to reproduce (if any)
Preconditions
- register a module
- in module onload function, register a notifycation callback:
RedisModule_SubscribeToKeyspaceEvents(ctx, mask, SubCallback)
//in notifycation callback
if (keya is expired) {
use RM_Call delete keyb
}
Step 1、Set keya and keyb 2、set expire keya and keyb, keya and keyb may be continuously stored in the expire dict 3、activeExpireCycle expire keya，then trigger notifycation callback. keyb will be deleted in the callback.
``` //expire.c:262: activeExpireCycle() redis 6.0.4 / Scan the current bucket of the current table. / checked_buckets++; while(de) { / Get the next entry now since this entry may get * deleted. / dictEntry *e = de; // e is keya, the next entry is keyb de = de->next; //de point keyb
ttl = dictGetSignedIntegerVal(e)-now;
// keya will be expired, and keyb will be deleted in the notifycation callback
// then "de" is invalid, next cycle may crash
if (activeExpireCycleTryExpire(db,e,now)) expired++;
if (ttl > 0) {
/* We want the average TTL of keys yet
* not expired. */
ttl_sum += ttl;
ttl_samples++;
}
sampled++;
}
```
Comment From: ShooterIT
It is a interesting bug :) What a coincidence! In most cases, one hash slot doesn't have many entries. But your two keys both are in the same slot.