Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@cassandra.apache.org
Received-SPF: unknown (nike.apache.org: error in processing during lookup of
 peter@librato.com)
MIME-Version: 1.0
Date: Fri, 15 Aug 2014 00:45:42 -0400
Message-ID: 
 <CA+qbKnx_sUwKFMArQUo0MdDZeEOD2U6dgKxnX=4T26JBftMLTA@mail.gmail.com>
Subject: Bootstrap failures: unable to find sufficient sources for streaming
 range
From: Peter Haggerty <peter.haggerty@librato.com>
To: user@cassandra.apache.org
Content-Type: text/plain; charset=UTF-8

When adding nodes via bootstrap to a 27 node 2.0.9 cluster with a
cluster-wide phi_convict_threshold of 12 the nodes fail to bootstrap.
This worked a half dozen times in the past few weeks as we've scaled
this cluster from 21 to 24 and then to 27 nodes. There have been no
configuration or Cassandra version changes since the cluster was
booted several weeks ago. This is adding a single node at a time just
as we've done before.

When using a phi of 16 on the node that is bootstrapping we've had one
failure and one success. Adjusting RING_DELAY from 30 seconds to 45
doesn't appear to help.

We have DEBUG level logs for a successful attempt and a failed attempt
but they seem quite similar in behavior, even bad behavior like ERRORS
reported by MigrationTask.java and FailureDetector.java.


In the failed attempts the bootstrap immediately falls over with
"unable to find ...":
java.lang.IllegalStateException: unable to find sufficient sources for
streaming range (1445230693272554509,1449885986247309687]

The logs clearly show that it knows where those ranges can be found:
DEBUG [main] 2014-08-14 18:56:45,019 RangeStreamer.java (line 122)
Bootstrap: range (1445230693272554509,1449885986247309687] exists on
/10.11.12.13
DEBUG [main] 2014-08-14 18:56:45,019 RangeStreamer.java (line 122)
Bootstrap: range (1445230693272554509,1449885986247309687] exists on
/10.11.12.14

If you look for the various non-debug log lines for these addresses
you'll see some odd behavior, but you see similar odd behavior in the
logs of the node that is able to successfully bootstrap.
$ grep '10.11.12.13' system.log | grep -v ^DEBUG
 INFO [GossipStage:1] 2014-08-14 18:56:09,870 Gossiper.java (line 910)
Node /10.11.12.13 is now part of the cluster
 INFO [GossipStage:1] 2014-08-14 18:56:15,267 Gossiper.java (line 910)
Node /10.11.12.13 is now part of the cluster
 INFO [HANDSHAKE-/10.11.12.13] 2014-08-14 18:56:45,571
OutboundTcpConnection.java (line 386) Handshaking version with
/10.11.12.13
 INFO [RequestResponseStage:5] 2014-08-14 18:56:45,579 Gossiper.java
(line 876) InetAddress /10.11.12.13 is now UP
 INFO [RequestResponseStage:2] 2014-08-14 18:56:45,579 Gossiper.java
(line 876) InetAddress /10.11.12.13 is now UP
 INFO [RequestResponseStage:7] 2014-08-14 18:56:45,580 Gossiper.java
(line 876) InetAddress /10.11.12.13 is now UP
 INFO [RequestResponseStage:1] 2014-08-14 18:56:45,579 Gossiper.java
(line 876) InetAddress /10.11.12.13 is now UP
 INFO [RequestResponseStage:8] 2014-08-14 18:56:45,579 Gossiper.java
(line 876) InetAddress /10.11.12.13 is now UP

$ grep '10.11.12.14' system.log | grep -v ^DEBUG
 INFO [GossipStage:1] 2014-08-14 18:56:09,865 Gossiper.java (line 910)
Node /10.11.12.14 is now part of the cluster
 INFO [GossipStage:1] 2014-08-14 18:56:15,106 Gossiper.java (line 910)
Node /10.11.12.14 is now part of the cluster

The general order of events, as told by JOINING lines:
$ grep 'JOINING' system.log
 INFO [main] 2014-08-14 18:56:10,638 StorageService.java (line 1009)
JOINING: waiting for ring information
 INFO [main] 2014-08-14 18:56:14,640 StorageService.java (line 1009)
JOINING: schema complete, ready to bootstrap
 INFO [main] 2014-08-14 18:56:14,640 StorageService.java (line 1009)
JOINING: waiting for pending range calculation
 INFO [main] 2014-08-14 18:56:14,641 StorageService.java (line 1009)
JOINING: calculation complete, ready to bootstrap
 INFO [main] 2014-08-14 18:56:14,641 StorageService.java (line 1009)
JOINING: getting bootstrap token
 INFO [main] 2014-08-14 18:56:14,712 StorageService.java (line 1009)
JOINING: sleeping 30000 ms for pending range setup
 INFO [main] 2014-08-14 18:56:44,713 StorageService.java (line 1009)
JOINING: Starting to bootstrap...


Thanks in advance for any suggestions.


Peter