Redis crash bgsave failed - Failed assertion: <no assertion failed> (<no file>:0)

[Mei-Zhao]

Background saving started by pid 7798

=== REDIS BUG REPORT START: Cut & paste starting from here ===
7798:C 08 Jan 16:45:56.809 # Redis 4.0.7 crashed by signal: 11
7798:C 08 Jan 16:45:56.809 # Crashed running the instruction at: 0x442c66
7798:C 08 Jan 16:45:56.809 # Accessing address: 0x16831a595a3
7798:C 08 Jan 16:45:56.809 # Failed assertion: (:0)

------ STACK TRACE ------
EIP:
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x442c66]

Backtrace:
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x463479]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x463b7c]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7fa3c73b6330]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x442c66]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x44363e]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x443bcc]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x4440b7]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x4442ec]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x4468af]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x425e8e]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x426537]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x435895]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x42037d]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x42065b]
redis-rdb-bgsave 0.0.0.0:7004 cluster[0x41d53f]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7fa3c7002f45]
redis-rdb-bgsave 0.0.0.0:7004 [cluster][0x41d78a]
------ INFO OUTPUT ------

Server^M

redis_version:4.0.7^M
redis_git_sha1:00000000^M
redis_git_dirty:0^M
redis_build_id:b1ca8cb8007db237^M
redis_mode:cluster^M
os:Linux 4.4.0-31-generic x86_64^M
arch_bits:64^M
multiplexing_api:epoll^M
atomicvar_api:atomic-builtin^M
gcc_version:4.8.4^M
process_id:7798^M
run_id:99a0357ab6bae87dbc55a4bb56bf1a6274f733ec^M
tcp_port:7004^M
uptime_in_seconds:22345^M
uptime_in_days:0^M
hz:10^M
lru_clock:3433236^M
executable:/home/qboxserver/kodo-redis-cluster-io2/_package/redis-server^M
config_file:/home/qboxserver/kodo-redis-cluster-io2/_package/redis.conf^M
^M

Clients^M

connected_clients:1448^M
client_longest_output_list:0^M
client_biggest_input_buf:0^M
blocked_clients:0^M
^M

Memory^M

used_memory:10264168703^M
used_memory_human:9.56G^M
used_memory_rss:13801140224^M
used_memory_rss_human:12.85G^M
used_memory_peak:12753300819^M
used_memory_peak_human:11.88G^M
used_memory_peak_perc:80.48%^M
used_memory_overhead:2161257152^M
used_memory_startup:1979968^M
used_memory_dataset:8102911551^M
used_memory_dataset_perc:78.96%^M
total_system_memory:101351088128^M
total_system_memory_human:94.39G^M
used_memory_lua:37888^M
used_memory_lua_human:37.00K^M
maxmemory:10737418240^M
maxmemory_human:10.00G^M
maxmemory_policy:allkeys-lru^M
mem_fragmentation_ratio:1.34^M
mem_allocator:libc^M
active_defrag_running:0^M
lazyfree_pending_objects:0^M
^M

Persistence^M

loading:0^M
rdb_changes_since_last_save:3442305^M
rdb_bgsave_in_progress:0^M
rdb_last_save_time:1546931238^M
rdb_last_bgsave_status:err^M
rdb_last_bgsave_time_sec:106^M
rdb_current_bgsave_time_sec:-1^M
rdb_last_cow_size:5697703936^M
aof_enabled:0^M
aof_rewrite_in_progress:0^M
aof_rewrite_scheduled:0^M
aof_last_rewrite_time_sec:-1^M
aof_current_rewrite_time_sec:-1^M
aof_last_bgrewrite_status:ok^M
aof_last_write_status:ok^M
aof_last_cow_size:0^M
^M

Stats^M

total_connections_received:104441^M
total_commands_processed:94165618^M
instantaneous_ops_per_sec:4583^M
total_net_input_bytes:16245240629^M
total_net_output_bytes:60742776562^M
instantaneous_input_kbps:536.92^M
instantaneous_output_kbps:285.95^M
rejected_connections:0^M
sync_full:26^M
sync_partial_ok:0^M
sync_partial_err:11^M
expired_keys:1522240^M
evicted_keys:9400441^M
keyspace_hits:34266086^M
keyspace_misses:20309817^M
pubsub_channels:0^M
pubsub_patterns:0^M
latest_fork_usec:362171^M
migrate_cached_sockets:0^M
slave_expires_tracked_keys:0^M
active_defrag_hits:0^M
active_defrag_misses:0^M
active_defrag_key_hits:0^M
active_defrag_key_misses:0^M
^M

Replication^M

role:master^M
connected_slaves:0^M
master_replid:5c76900ffe23f8218c5afb533b6243c283ae00c7^M
master_replid2:0000000000000000000000000000000000000000^M
master_repl_offset:176621661084^M
second_repl_offset:-1^M
repl_backlog_active:1^M
repl_backlog_size:314572800^M
repl_backlog_first_byte_offset:176307088285^M
repl_backlog_histlen:314572800^M
^M

CPU^M

used_cpu_sys:5.41^M
used_cpu_user:37.46^M
used_cpu_sys_children:0.00^M
used_cpu_user_children:0.00^M
^M

Commandstats^M

cmdstat_replconf:calls=52,usec=72,usec_per_call=1.38^M
cmdstat_ping:calls=75,usec=23,usec_per_call=0.31^M
cmdstat_bgsave:calls=1,usec=3,usec_per_call=3.00^M
cmdstat_command:calls=60,usec=33516,usec_per_call=558.60^M
cmdstat_psync:calls=26,usec=10007216,usec_per_call=384892.94^M
cmdstat_select:calls=1,usec=1,usec_per_call=1.00^M
cmdstat_get:calls=54828120,usec=179513668,usec_per_call=3.27^M
cmdstat_keys:calls=1,usec=43705458,usec_per_call=43705456.00^M
cmdstat_info:calls=3023,usec=3631601,usec_per_call=1201.32^M
cmdstat_latency:calls=5940,usec=27733,usec_per_call=4.67^M
cmdstat_cluster:calls=23918,usec=2238829,usec_per_call=93.60^M
cmdstat_set:calls=11091488,usec=178472054,usec_per_call=16.09^M
cmdstat_ttl:calls=1,usec=4,usec_per_call=4.00^M
cmdstat_del:calls=28203962,usec=69769726,usec_per_call=2.47^M
cmdstat_dbsize:calls=102,usec=103,usec_per_call=1.01^M
cmdstat_slowlog:calls=5876,usec=65516,usec_per_call=11.15^M
cmdstat_config:calls=2972,usec=343050,usec_per_call=115.43^M
^M

Cluster^M

cluster_enabled:1^M
^M

Keyspace^M

db0:keys=20003329,expires=19907676,avg_ttl=52859382^M

------ CURRENT CLIENT INFO ------
id=104441 addr=127.0.0.1:24039 fd=1523 name= age=16 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=bgsave
argv[0]: 'bgsave'
3928:M 08 Jan 16:45:57.740 # Background saving terminated by signal 11

------ DUMPING CODE AROUND EIP ------
Symbol: rdbSaveObjectType (base: 0x442c60)
Module: redis-rdb-bgsave 0.0.0.0:7004 [cluster] (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x442c60 -D -b binary -m i386:x86-64 /tmp/dump.bin

10077:C 08 Jan 17:14:04.149 # dump of function (hexdump of 134 bytes):
55534883ec180fb61689d083e00f83f8050f87b90100004889fbff24c590084c000f1f800000000083e2f080fa500f84bc01000080fa200f85550200004885ffc644240e04743a488b4720488d6c240e4885c074100f1f00ba010000004889ee4889dfffd0ba010000004889ee4889dfff53084885c00f844401000048834330014883c418b8

[Mei-Zhao]

1.slave of this node crushed, the debug report info as follow:
=== REDIS BUG REPORT START: Cut & paste starting from here ===
30506:S 08 Jan 15:09:08.029 # === ASSERTION FAILED OBJECT CONTEXT ===
30506:S 08 Jan 15:09:08.029 # Object type: 0
30506:S 08 Jan 15:09:08.029 # Object encoding: 0
30506:S 08 Jan 15:09:08.029 # Object refcount: 1
30506:S 08 Jan 15:09:08.029 # Object raw string len: 56
30506:S 08 Jan 15:09:08.029 # Object raw string content: "aW9fdjI6N3hrNXRkOndlaXhpbl9MVEU1TVRFME56QXpPRFU9MC5qcGc="
30506:S 08 Jan 15:09:08.029 # === ASSERTION FAILED ===
30506:S 08 Jan 15:09:08.029 # ==> db.c:171 'retval == DICT_OK' is not true
30506:S 08 Jan 15:09:08.029 # (forcing SIGSEGV to print the bug report.)
30506:S 08 Jan 15:09:08.029 # Redis 4.0.7 crashed by signal: 11
30506:S 08 Jan 15:09:08.029 # Crashed running the instruction at: 0x4613aa
30506:S 08 Jan 15:09:08.029 # Accessing address: 0xffffffffffffffff
30506:S 08 Jan 15:09:08.029 # Failed assertion: retval == DICT_OK (db.c:171)

I checked the dump.rdb use rdbtools and duplicated key was found. Del the key from master success,then slave want to sync with master, master crashed as up description

[oranagra]

@Mei-Zhao do you have any clue how that duplicate key was created?
i see that the only write command that master had was SET, but maybe it got it from an RDB file or replication stream.