Thanks to driftx from cassandra IRC channel for helping out.
This was resolved by increasing the rpc timeout for the bootstrap process.

On Wed, Sep 15, 2010 at 11:43 AM, Gurpreet Singh
<gurpreet.si...@gmail.com>wrote:

> This problem still stays unresolved despite numerous restarts to the
> cluster. I cant seem to find a way out of this one, and I am not really
> looking for a workaround, kinda need this to work if i need to go to
> production.
>
> Turned on the ALL logging in log4j, and now I see the following exception
> (EOFException) on the destination. After receiving each file, it seems to be
> throwing this exception. The transfer is successful except for this
> exception. The source successful declares the transfer complete. But the
> destination does not move out of the bootstrapping mode, and just sits
> there.
>
> DEBUG [Thread-15] 2010-09-15 10:56:59,767 IncomingStreamReader.java (line
> 65) Receiving stream: finished reading chunk, awaiting more
> DEBUG [Thread-15] 2010-09-15 10:56:59,767 IncomingStreamReader.java (line
> 87) Removing stream context
> /data/cassandra/datadir/cassandradb/userdata/user_list_items-tmp-1-Index.db:522051369
> DEBUG [Thread-15] 2010-09-15 10:56:59,767 StreamCompletionHandler.java
> (line 73) Sending a streaming finished message with
> org.apache.cassandra.streaming.completedfilesta...@54828e7 to IP1
> TRACE [Thread-15] 2010-09-15 10:56:59,769 IncomingTcpConnection.java (line
> 82) eof reading from socket; closing
> java.io.EOFException
>         at java.io.DataInputStream.readInt(Unknown Source)
>         at
> org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:59)
> DEBUG [Thread-16] 2010-09-15 10:56:59,812 IncomingStreamReader.java (line
> 51) Receiving stream
> DEBUG [Thread-16] 2010-09-15 10:56:59,812 IncomingStreamReader.java (line
> 54) Creating file for
> /data/cassandra/datadir/cassandradb/userdata/user_list_items-tmp-1-Filter.db
> DEBUG [Thread-16] 2010-09-15 10:56:59,876 IncomingStreamReader.java (line
> 65) Receiving stream: finished reading chunk, awaiting more
> DEBUG [Thread-16] 2010-09-15 10:56:59,876 IncomingStreamReader.java (line
> 87) Removing stream context
> /data/cassandra/datadir/cassandradb/userdata/user_list_items-tmp-1-Filter.db:7489045
> DEBUG [Thread-16] 2010-09-15 10:56:59,876 StreamCompletionHandler.java
> (line 73) Sending a streaming finished message with
> org.apache.cassandra.streaming.completedfilesta...@7b41a32f to IP1
> TRACE [Thread-16] 2010-09-15 10:56:59,876 IncomingTcpConnection.java (line
> 82) eof reading from socket; closing
> java.io.EOFException
>         at java.io.DataInputStream.readInt(Unknown Source)
>         at
> org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:59)
>
> /G
>
> On Tue, Sep 14, 2010 at 11:40 AM, Gurpreet Singh <gurpreet.si...@gmail.com
> > wrote:
>
>> Hi Vineet,
>> I have tracked the nodetool streams to completion each time. Below are the
>> logs on the source and destination node. There are 3 sstables being
>> transferred, and the transfer seems to be successful. However, after the
>> streams finish, the source prints out messages about the dropped messages,
>> which may point to the problem. ideas? I checked port 7000 is open for
>> communication. 9160 is not up on the node being bootstrapped, but that comes
>> up after the node is bootstrapped, is that right?
>>
>> Thanks a ton,
>> /G
>>
>> *Logs on the source node (IP2):*
>> *
>> *
>> INFO [STREAM-STAGE:1] 2010-09-14 09:54:07,900 StreamOut.java (line 79)
>> Flushing memtables for userdata...
>>  INFO [STREAM-STAGE:1] 2010-09-14 09:54:07,900 StreamOut.java (line 95)
>> Performing anticompaction ...
>>  INFO [COMPACTION-POOL:1] 2010-09-14 09:54:07,900 CompactionManager.java
>> (line 339) AntiCompacting
>> [org.apache.cassandra.io.SSTableReader(path='/data/cassandra/datadir/cassandradb/userdata/user_list_items-5823-Data.db')]
>>  INFO [GC inspection] 2010-09-14 09:56:54,712 GCInspector.java (line 129)
>> GC for ParNew: 212 ms, 29033016 reclaimed leaving 579419360 used; max is
>> 4415946752
>>  INFO [COMPACTION-POOL:1] 2010-09-14 10:18:06,508 CompactionManager.java
>> (line 396) AntiCompacted to
>> /data/cassandra/datadir/cassandradb/userdata/stream/user_list_items-5825-Data.db.
>>  49074138589/36770836242 bytes for 5990912 keys.  Time: 1438607ms.
>>  INFO [COMPACTION-POOL:1] 2010-09-14 10:18:06,528 CompactionManager.java
>> (line 339) AntiCompacting
>> [org.apache.cassandra.io.SSTableReader(path='/data/cassandra/datadir/cassandradb/userdata/user-22-Data.db')]
>>  INFO [COMPACTION-POOL:1] 2010-09-14 10:18:08,839 CompactionManager.java
>> (line 396) AntiCompacted to
>> /data/mysql/cassandrastorage/userdata/stream/user-24-Data.db.
>>  28185244/21126422 bytes for 47722 keys.  Time: 2310ms.
>>  INFO [COMPACTION-POOL:1] 2010-09-14 10:18:08,840 CompactionManager.java
>> (line 339) AntiCompacting
>> [org.apache.cassandra.io.SSTableReader(path='/data/cassandra/datadir/cassandradb/userdata/user_lists-502-Data.db')]
>>  INFO [COMPACTION-POOL:1] 2010-09-14 10:21:08,606 CompactionManager.java
>> (line 396) AntiCompacted to
>> /data/mysql/cassandrastorage/userdata/stream/user_lists-504-Data.db.
>>  2927724285/2195768325 bytes for 3976118 keys.  Time: 179766ms.
>>  INFO [STREAM-STAGE:1] 2010-09-14 10:21:08,607 StreamOut.java (line 127)
>> Stream context metadata
>> /data/cassandra/datadir/cassandradb/userdata/stream/user_list_items-5825-Index.db:522051369,
>>  3
>> sstables./data/cassandra/datadir/cassandradb/userdata/stream/user_list_items-5825-Filter.db:7489045,
>>  3
>> sstables./data/cassandra/datadir/cassandradb/userdata/stream/user_list_items-5825-Data.db:36770836242,
>>  3
>> sstables./data/mysql/cassandrastorage/userdata/stream/user-24-Index.db:3373143,
>>  3
>> sstables./data/mysql/cassandrastorage/userdata/stream/user-24-Filter.db:59965,
>>  3
>> sstables./data/mysql/cassandrastorage/userdata/stream/user-24-Data.db:21126422,
>>  3
>> sstables./data/mysql/cassandrastorage/userdata/stream/user_lists-504-Index.db:282956452,
>>  3
>> sstables./data/mysql/cassandrastorage/userdata/stream/user_lists-504-Filter.db:4970125,
>>  3
>> sstables./data/mysql/cassandrastorage/userdata/stream/user_lists-504-Data.db:2195768325
>>  INFO [STREAM-STAGE:1] 2010-09-14 10:21:08,608 StreamOut.java (line 132)
>> Sending a stream initiate message to IP1...
>>  INFO [STREAM-STAGE:1] 2010-09-14 10:21:08,608 StreamOut.java (line 137)
>> Waiting for transfer to IP1 to complete
>>  *WARN [DroppedMessagesLogger] 2010-09-14 10:28:00,592
>> MessagingService.java (line 501) Dropped 9 messages in the last 1000ms*
>> * *INFO [STREAM-STAGE:1] 2010-09-14 10:28:00,605 StreamOut.java (line
>> 141) Done with transfer to IP1
>>  INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 10:28:00,670
>> SSTableDeletingReference.java (line 104) Deleted
>> /data/cassandra/datadir/cassandradb/system/LocationInfo-17-Data.db
>>  *WARN [DroppedMessagesLogger] 2010-09-14 10:28:01,602
>> MessagingService.java (line 501) Dropped 1 messages in the last 1000ms*
>> * *INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 10:28:06,133
>> SSTableDeletingReference.java (line 104) Deleted
>> /data/mysql/cassandrastorage/system/LocationInfo-19-Data.db
>>  INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 10:28:06,134
>> SSTableDeletingReference.java (line 104) Deleted
>> /data/cassandra/datadir/cassandradb/system/LocationInfo-18-Data.db
>>  INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 10:28:06,134
>> SSTableDeletingReference.java (line 104) Deleted
>> /data/cassandra/datadir/cassandradb/system/LocationInfo-20-Data.db
>>
>>
>>
>> *Logs on new node being bootstrapped (IP1):*
>>
>> INFO [main] 2010-09-14 09:53:37,788 BootStrapper.java (line 104) New token
>> will be 149298847080838649048722691811739653739 to assume load from IP2
>>  INFO [main] 2010-09-14 09:53:37,789 StorageService.java (line 388)
>> Joining: sleeping 30000 ms for pending range setup
>>  INFO [main] 2010-09-14 09:54:07,792 StorageService.java (line 388)
>> Bootstrapping
>>  INFO [Thread-17] 2010-09-14 10:26:40,699 SSTableReader.java (line 120)
>> Sampling index for
>> /data/mysql/cassandrastorage/userdata/user_list_items-2-Data.db
>>  INFO [Thread-17] 2010-09-14 10:26:51,453 StreamCompletionHandler.java
>> (line 64) Streaming added
>> /data/mysql/cassandrastorage/userdata/user_list_items-2-Data.db
>>  INFO [Thread-23] 2010-09-14 10:26:52,219 SSTableReader.java (line 120)
>> Sampling index for
>> /data/cassandra/datadir/cassandradb/userdata/user-2-Data.db
>>  INFO [Thread-23] 2010-09-14 10:26:52,311 StreamCompletionHandler.java
>> (line 64) Streaming added
>> /data/cassandra/datadir/cassandradb/userdata/user-2-Data.db
>>  INFO [Timer-0] 2010-09-14 10:27:13,676 Gossiper.java (line 180)
>> InetAddress IP2 is now dead.
>>  INFO [Thread-26] 2010-09-14 10:27:18,858 SSTableReader.java (line 120)
>> Sampling index for
>> /data/cassandra/datadir/cassandradb/userdata/user_lists-2-Data.db
>>  INFO [Thread-26] 2010-09-14 10:27:24,645 StreamCompletionHandler.java
>> (line 64) Streaming added
>> /data/cassandra/datadir/cassandradb/userdata/user_lists-2-Data.db
>>  INFO [HINTED-HANDOFF-POOL:1] 2010-09-14 10:28:00,605
>> HintedHandOffManager.java (line 165) Started hinted handoff for endPoint IP2
>>  INFO [GMFD:1] 2010-09-14 10:28:00,605 Gossiper.java (line 578)
>> InetAddress IP2 is now UP
>>  INFO [HINTED-HANDOFF-POOL:1] 2010-09-14 10:28:00,606
>> HintedHandOffManager.java (line 222) Finished hinted handoff of 0 rows to
>> endpoint IP2
>>  INFO [FLUSH-TIMER] 2010-09-14 10:57:52,381 ColumnFamilyStore.java (line
>> 357) LocationInfo has reached its threshold; switching in a fresh Memtable
>> at
>> CommitLogContext(file='/data/cassandra/datadir/commitlog/CommitLog-1284483127473.log',
>> position=1353)
>>  INFO [FLUSH-TIMER] 2010-09-14 10:57:52,382 ColumnFamilyStore.java (line
>> 609) Enqueuing flush of memtable-locationi...@2057079871(210 bytes, 6
>> operations)
>>  INFO [FLUSH-WRITER-POOL:1] 2010-09-14 10:57:52,382 Memtable.java (line
>> 148) Writing memtable-locationi...@2057079871(210 bytes, 6 operations)
>>  INFO [FLUSH-WRITER-POOL:1] 2010-09-14 10:57:52,464 Memtable.java (line
>> 162) Completed flushing
>> /data/cassandra/datadir/cassandradb/system/LocationInfo-10-Data.db
>>
>>
>> On Tue, Sep 14, 2010 at 10:52 AM, vineet daniel 
>> <vineetdan...@gmail.com>wrote:
>>
>>> Hi Gurpreet
>>>
>>> What is the output of  nodetool -h <hostname/IP> streams  -->( to see
>>> what is going on between the nodes) . If you dont see anything happening
>>> try switching off firewall or iptables.
>>>
>>>
>>> Regards
>>> Vineet Daniel
>>> Cell          : +918106217121
>>> Websites :
>>> Blog <http://vinetedaniel.blogspot.com>   |   
>>> Linkedin<http://in.linkedin.com/in/vineetdaniel>
>>> |  Twitter <https://twitter.com/vineetdaniel>
>>>
>>>
>>>
>>>
>>>
>>> On Tue, Sep 14, 2010 at 11:11 PM, Gurpreet Singh <
>>> gurpreet.si...@gmail.com> wrote:
>>>
>>>> I tried this again, it happenned yet again.
>>>> This time while the transfer messages seemed tobe in order, i also
>>>> noticed that the source logs talk about having 9 dropped messages in the
>>>> last 1000 ms. The only activity on the whole cluster is this bootstrapping,
>>>> there is no read/write traffic going on.
>>>>
>>>> /G
>>>>
>>>> On Tue, Sep 14, 2010 at 10:05 AM, Gurpreet Singh <
>>>> gurpreet.si...@gmail.com> wrote:
>>>>
>>>>> I am using cassandra 0.6.5.
>>>>>
>>>>>
>>>>> On Tue, Sep 14, 2010 at 9:16 AM, Gurpreet Singh <
>>>>> gurpreet.si...@gmail.com> wrote:
>>>>>
>>>>>> Hi,
>>>>>> I have a cassandra cluster of 4 machines, and I am trying to bootstrap
>>>>>> 2 more machines, one at a time.
>>>>>> For both these machines, the bootstrapping stays stuck after the
>>>>>> streaming is done.
>>>>>>
>>>>>> When the nodes come up for bootstrapping, I see all the relevant
>>>>>> messages about getting a new token, assuming load from a particular 
>>>>>> host. I
>>>>>> see a couple of nodes anticompacting data to send, and at a later point 
>>>>>> the
>>>>>> node that is bootstrapping prints the right streaming mesgs. However, 
>>>>>> once
>>>>>> the streaming is over, the node just doesnt do anything. Previously while
>>>>>> bootstrapping, I have seen that after the streaming is done, the node
>>>>>> restarts and becomes part of the ring by itself. I dont see this 
>>>>>> behaviour
>>>>>> with both the nodes I tried today.
>>>>>> I even restarted all the nodes in the cluster, and tried bootstrapping
>>>>>> one of the nodes again, but it again was stuck after streaming. It seems 
>>>>>> to
>>>>>> have copied the relevant load as well.
>>>>>> Any ideas as to what could be going on here?
>>>>>>
>>>>>> /G
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>
>

Reply via email to