redis-io icon indicating copy to clipboard operation
redis-io copied to clipboard

Published 20 hours ago • verified publisher icon redis

redis-cluster error on bgsave

Open shcherbak opened this issue 6 years ago • 1 comments

=== REDIS BUG REPORT START: Cut & paste starting from here === 17971:C 28 Mar 01:16:12.789 # Redis 3.2.8 crashed by signal: 11 17971:C 28 Mar 01:16:12.789 # Crashed running the instuction at: 0x55fffbc29420 17971:C 28 Mar 01:16:12.789 # Accessing address: 0x1bacffbff 17971:C 28 Mar 01:16:12.789 # Failed assertion: (:0)

------ STACK TRACE ------ 29555:M 28 Mar 01:16:12.795 - DB 0: 77948119 keys (63009029 volatile) in 134217728 slots HT. 29555:M 28 Mar 01:16:12.796 - 0 clients connected (1 slaves), 25658747736 bytes in use EIP: redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc29420]

Backtrace: redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc69105] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc698d0] /lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7fe8db647890] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc29420] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc28544] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc408e4] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc49da4] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc4a163] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc4a48b] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc4663b] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc469db] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc2c4d3] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc2f9f0] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc3d28d] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc260a7] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc2642b] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc232a4] /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7fe8db2aeb45] redis-rdb-bgsave 0.0.0.0:6379 cluster[0x55fffbc23459]

------ INFO OUTPUT ------

Server

redis_version:3.2.8 redis_git_sha1:00000000 redis_git_dirty:0 redis_build_id:bb0ba4e36835f109 redis_mode:cluster os:Linux 4.9.0-0.bpo.5-amd64 x86_64 arch_bits:64 multiplexing_api:epoll gcc_version:4.9.2 process_id:17971 run_id:2075cea0e92c1e863c2e3267733b5fd3e5e41e50 tcp_port:6379 uptime_in_seconds:9019 uptime_in_days:0 hz:10 lru_clock:12242940 executable:/usr/bin/redis-server config_file:/etc/redis/redis.conf

Clients

connected_clients:0 client_longest_output_list:0 client_biggest_input_buf:0 blocked_clients:0

Memory

used_memory:25658785280 used_memory_human:23.90G used_memory_rss:25734279168 used_memory_rss_human:23.97G used_memory_peak:25658862480 used_memory_peak_human:23.90G total_system_memory:50654191616 total_system_memory_human:47.18G used_memory_lua:37888 used_memory_lua_human:37.00K maxmemory:36507222016 maxmemory_human:34.00G maxmemory_policy:volatile-lru mem_fragmentation_ratio:1.00 mem_allocator:jemalloc-3.6.0

Persistence

loading:0 rdb_changes_since_last_save:0 rdb_bgsave_in_progress:0 rdb_last_save_time:1522183361 rdb_last_bgsave_status:err rdb_last_bgsave_time_sec:332 rdb_current_bgsave_time_sec:-1 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_last_write_status:ok

Stats

total_connections_received:327 total_commands_processed:699 instantaneous_ops_per_sec:0 total_net_input_bytes:7941808292 total_net_output_bytes:417452 instantaneous_input_kbps:0.00 instantaneous_output_kbps:0.00 rejected_connections:0 sync_full:12 sync_partial_ok:0 sync_partial_err:0 expired_keys:1 evicted_keys:0 keyspace_hits:0 keyspace_misses:0 pubsub_channels:0 pubsub_patterns:0 latest_fork_usec:657925 migrate_cached_sockets:0

Replication

role:master connected_slaves:1 slave0:ip=192.168.210.27,port=6379,state=wait_bgsave,offset=0,lag=0 master_repl_offset:66421 repl_backlog_active:1 repl_backlog_size:1048576 repl_backlog_first_byte_offset:60863 repl_backlog_histlen:5559

CPU

used_cpu_sys:10.67 used_cpu_user:175.20 used_cpu_sys_children:0.00 used_cpu_user_children:0.00

Commandstats

cmdstat_ping:calls=352,usec=131,usec_per_call=0.37 cmdstat_psync:calls=11,usec=7275840,usec_per_call=661440.00 cmdstat_replconf:calls=24,usec=98,usec_per_call=4.08 cmdstat_info:calls=151,usec=19571,usec_per_call=129.61 cmdstat_config:calls=147,usec=4252,usec_per_call=28.93 cmdstat_cluster:calls=14,usec=11053,usec_per_call=789.50

Cluster

cluster_enabled:1

Keyspace

db0:keys=77948119,expires=63009029,avg_ttl=1101602189 hash_init_value: 1521674720

------ CLIENT LIST OUTPUT ------ id=329 addr=192.168.210.27:23833 fd=13 name= age=0 idle=0 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=psync

------ CURRENT CLIENT INFO ------ id=329 addr=192.168.210.27:23833 fd=13 name= age=0 idle=0 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=psync argv[0]: 'PSYNC' argv[1]: '?' argv[2]: '-1'

------ REGISTERS ------ 17971:C 28 Mar 01:16:12.805 # RAX:000055fffbeea1e0 RBX:00007fe8da8f1000 RCX:00000001bacffc00 RDX:0000000003c17105 RDI:00000001bacffc00 RSI:00000001bacffc00 RBP:00000001bacffc00 RSP:00007ffe3445ed98 R8 :00007fe8da815560 R9 :00007fe2c0971983 R10:000000000000003f R11:0000000000000000 R12:00007fe8da8672e0 R13:00007fe2c09719c3 R14:00007fe8da867320 R15:00007fe8da8672c0 RIP:000055fffbc29420 EFL:0000000000010246 CSGSFS:002b000000000033 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda7) -> 00007ffe3445eebc 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda6) -> 00007ffe3445ee3e 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda5) -> 00007ffe3445ee3d 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda4) -> 000055fffbc49da4 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda3) -> 00007ffe3445ee40 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda2) -> 00007fe8da8f1000 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda1) -> 00007ffe3445eec0 17971:C 28 Mar 01:16:12.805 # (00007ffe3445eda0) -> 000055fffbc408e4 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed9f) -> 00007fe352987850 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed9e) -> 0000016269bc7532 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed9d) -> 00007fe2c09719c3 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed9c) -> 00007ffe3445ee40 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed9b) -> 00007ffe3445ee40 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed9a) -> 00007fe8da8f1000 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed99) -> 00007fe8da8f1000 17971:C 28 Mar 01:16:12.805 # (00007ffe3445ed98) -> 000055fffbc28544

------ FAST MEMORY TEST ------ *** Preparing to test memory region 55fffbeef000 (86016 bytes) *** Preparing to test memory region 7fe2c0800000 (26180845568 bytes) *** Preparing to test memory region 7fe8d93ff000 (8388608 bytes) *** Preparing to test memory region 7fe8d9c00000 (12582912 bytes) *** Preparing to test memory region 7fe8da800000 (8388608 bytes) *** Preparing to test memory region 7fe8db634000 (16384 bytes) *** Preparing to test memory region 7fe8db851000 (16384 bytes) *** Preparing to test memory region 7fe8dba8c000 (4096 bytes) *** Preparing to test memory region 7fe8dc073000 (4096 bytes) *** Preparing to test memory region 7fe8dc1a4000 (16384 bytes) *** Preparing to test memory region 7fe8dc1a8000 (4096 bytes) *** Preparing to test memory region 7fe8dc1b0000 (8192 bytes) *** Preparing to test memory region 7fe8dc1b4000 (4096 bytes)

shcherbak avatar Mar 28 '18 08:03 shcherbak

the same error reproduces on another slave. after restart (see stack trace below) slave can't connect to master. it is odd because master is available:

29189:S 29 Mar 20:01:11.181 * Connecting to MASTER ?:6379 29189:S 29 Mar 20:01:11.183 # Unable to connect to MASTER: Resource temporarily unavailable 29189:S 29 Mar 20:01:11.297 - Accepted 192.168.210.44:21596 29189:S 29 Mar 20:01:11.300 - Client closed connection syslog: Mar 29 19:28:22 bo-redis-cluster-07 kernel: [1133085.729815] redis-server[11177]: segfault at 36353334cd ip 000055e1c790ff64 sp 00007fff0be12cf0 error 4 in redis-server[55 e1c78d9000+e5000]

stack trace: `11177:S 29 Mar 19:27:12.347 * MASTER <-> SLAVE sync: Flushing old data

=== REDIS BUG REPORT START: Cut & paste starting from here === 11177:S 29 Mar 19:28:22.958 # Redis 3.2.8 crashed by signal: 11 11177:S 29 Mar 19:28:22.958 # Crashed running the instuction at: 0x55e1c7907105 11177:S 29 Mar 19:28:22.958 # Accessing address: 0xaca40 11177:S 29 Mar 19:28:22.958 # Failed assertion: (:0)

------ STACK TRACE ------ EIP: /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c7907105]

Backtrace: /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c793f105] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c793f8d0] /lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f6a3d85a890] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c7907105] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c78fe43a] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c78fee48] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c7918a6a] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c791a37a] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c78fc0a7] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c78fc42b] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c78f92a4] /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f6a3d4c1b45] /usr/bin/redis-server 0.0.0.0:6379 cluster[0x55e1c78f9459]

------ INFO OUTPUT ------

Server

redis_version:3.2.8 redis_git_sha1:00000000 redis_git_dirty:0 redis_build_id:bb0ba4e36835f109 redis_mode:cluster os:Linux 4.9.0-0.bpo.5-amd64 x86_64 arch_bits:64 multiplexing_api:epoll gcc_version:4.9.2 process_id:11177 run_id:78c1bf581dae64cef3d4772f3970ca24d03e78b2 tcp_port:6379 uptime_in_seconds:181820 uptime_in_days:2 hz:10 lru_clock:12394990 executable:/usr/bin/redis-server config_file:/etc/redis/redis.conf

Clients

connected_clients:661 client_longest_output_list:0 client_biggest_input_buf:0 blocked_clients:0

Memory

used_memory:21849073336 used_memory_human:20.35G used_memory_rss:26176933888 used_memory_rss_human:24.38G used_memory_peak:26410795144 used_memory_peak_human:24.60G total_system_memory:50654183424 total_system_memory_human:47.18G used_memory_lua:37888 used_memory_lua_human:37.00K maxmemory:36507222016 maxmemory_human:34.00G maxmemory_policy:volatile-lru mem_fragmentation_ratio:1.20 mem_allocator:jemalloc-3.6.0

Persistence

loading:0 rdb_changes_since_last_save:0 rdb_bgsave_in_progress:0 rdb_last_save_time:1522338127 rdb_last_bgsave_status:ok rdb_last_bgsave_time_sec:278 rdb_current_bgsave_time_sec:-1 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_last_write_status:ok

Stats

total_connections_received:710503 total_commands_processed:98159145 instantaneous_ops_per_sec:5 total_net_input_bytes:68654399368 total_net_output_bytes:15649898860 instantaneous_input_kbps:203063.88 instantaneous_output_kbps:50.51 rejected_connections:0 sync_full:2 sync_partial_ok:1 sync_partial_err:0 expired_keys:0 evicted_keys:0 keyspace_hits:0 keyspace_misses:0 pubsub_channels:0 pubsub_patterns:0 latest_fork_usec:844704 migrate_cached_sockets:0

Replication

role:slave master_host:192.168.210.25 master_port:6379 master_link_status:down master_last_io_seconds_ago:-1 master_sync_in_progress:1 slave_repl_offset:1 master_sync_left_bytes:0 master_sync_last_io_seconds_ago:0 master_link_down_since_seconds:615 slave_priority:100 slave_read_only:1 connected_slaves:0 master_repl_offset:0 repl_backlog_active:0 repl_backlog_size:1048576 repl_backlog_first_byte_offset:135444 repl_backlog_histlen:9226

CPU

used_cpu_sys:7513.40 used_cpu_user:21987.21 used_cpu_sys_children:816.94 used_cpu_user_children:9081.84

Commandstats

cmdstat_set:calls=6108441,usec=133729901,usec_per_call=21.89 cmdstat_setex:calls=80808830,usec=2117203889,usec_per_call=26.20 cmdstat_del:calls=5107658,usec=592890065,usec_per_call=116.08 cmdstat_hset:calls=246,usec=28956,usec_per_call=117.71 cmdstat_mset:calls=5455124,usec=125112351,usec_per_call=22.93 cmdstat_select:calls=2,usec=5,usec_per_call=2.50 cmdstat_ping:calls=16281,usec=10617,usec_per_call=0.65 cmdstat_psync:calls=3,usec=1227507,usec_per_call=409169.00 cmdstat_replconf:calls=2715,usec=8749,usec_per_call=3.22 cmdstat_info:calls=3027,usec=1872865,usec_per_call=618.72 cmdstat_config:calls=3017,usec=104086,usec_per_call=34.50 cmdstat_cluster:calls=591767,usec=242106073,usec_per_call=409.12 cmdstat_client:calls=62034,usec=226240,usec_per_call=3.65

Cluster

cluster_enabled:1

Keyspace

db0:keys=55303769,expires=63518939,avg_ttl=1112813656 hash_init_value: 1521491131

------ CLIENT LIST OUTPUT ------ 29189:M 29 Mar 19:28:25.976 * Node configuration loaded, I'm d1292e9823883bfa8bbc058f110480f9cdb2c098 .
.-__ ''-._ _.- . . ''-._ Redis 3.2.8 (00000000/0) 64 bit .- .-```. ```\/ _.,_ ''-._ ( ' , .-` | `, ) Running in cluster mode |`-._`-...-` __...-.-.|'_.-'| Port: 6379 | -. ._ / _.-' | PID: 29189 -._ -._ -./ .-' .-'
|-._-. -.__.-' _.-'_.-'| | -.-._ _.-'_.-' | http://redis.io -._ -._-..-'.-' .-'
|-._-. -.__.-' _.-'_.-'| | -.-._ _.-'_.-' | -._ -._-..-'_.-' _.-'
-._ -..-' _.-'
-._ _.-' -..-'

29189:M 29 Mar 19:28:25.977 # Server started, Redis version 3.2.8`

shcherbak avatar Mar 29 '18 17:03 shcherbak