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:
------ 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
Comment From: 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
Comment From: 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.