You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Cory Mintz <co...@gmail.com> on 2012/12/28 20:48:25 UTC

keyspace not copied to new node

I am trying to add a second node to a cluster that is currently a single
node, with a single key space on it.

* Cluster names are in sync
* They both have the same seed node (the first one)
* Both of the same snitch (Ec2Snitch)
* I am not filling in an initial_token on either

When I start the new node it joins the cluster and gets 50% of cluster.
Everything looks good, except the existing keyspace never is copied over
and the new node starts recording exceptions. This can also be seen in
nodetool that the Load has not been split.

Any help would be appreciated.

nodetool ring after join:
10.125.0.6      us-east     1a          Up     Normal  6.7 KB
50.02%              58390160951331053490088942307836377318
10.125.0.17     us-east     1a          Up     Normal  8.73 MB
49.98%              143434328038307359414303841008091364408

Log file for the existing node:
 INFO [GossipStage:1] 2012-12-28 18:40:23,945 Gossiper.java (line 848) Node
/10.125.0.6 has restarted, now UP
 INFO [GossipStage:1] 2012-12-28 18:40:23,946 Gossiper.java (line 816)
InetAddress /10.125.0.6 is now UP
 INFO [GossipStage:1] 2012-12-28 18:40:40,593 Gossiper.java (line 830)
InetAddress /10.125.0.6 is now dead.
 INFO [GossipTasks:1] 2012-12-28 18:41:09,292 Gossiper.java (line 644)
FatClient /10.125.0.6 has been silent for 30000ms, removing from gossip
 INFO [GossipStage:1] 2012-12-28 18:45:18,219 Gossiper.java (line 850) Node
/10.125.0.6 is now part of the cluster
 INFO [GossipStage:1] 2012-12-28 18:45:18,220 Gossiper.java (line 816)
InetAddress /10.125.0.6 is now UP
 INFO [GossipStage:1] 2012-12-28 18:46:17,471 ColumnFamilyStore.java (line
659) Enqueuing flush of Memtable-LocationInfo@782297898(35/43
serialized/live bytes, 1 ops)
 INFO [FlushWriter:6] 2012-12-28 18:46:17,471 Memtable.java (line 264)
Writing Memtable-LocationInfo@782297898(35/43 serialized/live bytes, 1 ops)
 INFO [FlushWriter:6] 2012-12-28 18:46:17,477 Memtable.java (line 305)
Completed flushing
/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-40-Data.db
(89 bytes) for commitlog position ReplayPosition(segmentId=1356717215209,
position=81403)
 INFO [CompactionExecutor:7] 2012-12-28 18:46:17,478 CompactionTask.java
(line 109) Compacting
[SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-39-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-40-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-38-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-37-Data.db')]
 INFO [CompactionExecutor:7] 2012-12-28 18:46:17,554 CompactionTask.java
(line 221) Compacted to
[/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-41-Data.db,].
702 to 435 (~61% of original) bytes for 4 keys at 0.005531MB/s.  Time: 75ms.
 INFO [MemoryMeter:1] 2012-12-28 19:00:28,396 Memtable.java (line 213)
CFS(Keyspace='system', ColumnFamily='HintsColumnFamily') liveRatio is
3.167859982557678 (just-counted was 3.167505874454515).  calculation took
24ms for 54 columns
 INFO [GossipStage:1] 2012-12-28 19:01:20,035 StorageService.java (line
1287) Removing token 58390160951331053490088942307836377318 for /10.125.0.6
 INFO [OptionalTasks:1] 2012-12-28 19:01:20,035 HintedHandOffManager.java
(line 180) Deleting any stored hints for /10.125.0.6
 INFO [OptionalTasks:1] 2012-12-28 19:01:20,037 ColumnFamilyStore.java
(line 659) Enqueuing flush of Memtable-HintsColumnFamily@614495718(23832/94370
serialized/live bytes, 73 ops)
 INFO [GossipStage:1] 2012-12-28 19:01:20,037 ColumnFamilyStore.java (line
659) Enqueuing flush of Memtable-LocationInfo@2119262016(35/43
serialized/live bytes, 1 ops)
 INFO [FlushWriter:7] 2012-12-28 19:01:20,038 Memtable.java (line 264)
Writing Memtable-HintsColumnFamily@614495718(23832/94370 serialized/live
bytes, 73 ops)
 INFO [FlushWriter:7] 2012-12-28 19:01:20,047 Memtable.java (line 305)
Completed flushing
/var/lib/cassandra/data/system/HintsColumnFamily/system-HintsColumnFamily-hf-5-Data.db
(66 bytes) for commitlog position ReplayPosition(segmentId=1356717215209,
position=114728)
 INFO [FlushWriter:7] 2012-12-28 19:01:20,048 Memtable.java (line 264)
Writing Memtable-LocationInfo@2119262016(35/43 serialized/live bytes, 1 ops)
 INFO [CompactionExecutor:8] 2012-12-28 19:01:20,051 CompactionTask.java
(line 109) Compacting
[SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily/system-HintsColumnFamily-hf-5-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily/system-HintsColumnFamily-hf-4-Data.db')]
 INFO [FlushWriter:7] 2012-12-28 19:01:20,052 Memtable.java (line 305)
Completed flushing
/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-42-Data.db
(89 bytes) for commitlog position ReplayPosition(segmentId=1356717215209,
position=114728)
 INFO [CompactionExecutor:8] 2012-12-28 19:01:20,059 CompactionTask.java
(line 221) Compacted to
[/var/lib/cassandra/data/system/HintsColumnFamily/system-HintsColumnFamily-hf-6-Data.db,].
132 to 66 (~50% of original) bytes for 1 keys at 0.012589MB/s.  Time: 5ms.

Log file for the new node:
 INFO [main] 2012-12-28 18:45:08,211 AbstractCassandraDaemon.java (line
101) Logging initialized
 INFO [main] 2012-12-28 18:45:08,216 AbstractCassandraDaemon.java (line
122) JVM vendor/version: OpenJDK 64-Bit Server VM/1.6.0_24
 INFO [main] 2012-12-28 18:45:08,217 AbstractCassandraDaemon.java (line
123) Heap size: 855638016/855638016
 INFO [main] 2012-12-28 18:45:08,222 AbstractCassandraDaemon.java (line
124) Classpath:
/usr/share/cassandra/lib/antlr-3.2.jar:/usr/share/cassandra/lib/avro-1.4.0-fixes.jar:/usr/share/cassandra/lib/avro-1.4.0-sources-fixes.jar:/usr/share/cassandra/lib/commons-cli-1.1.jar:/usr/share/cassandra/lib/commons-codec-1.2.jar:/usr/share/cassandra/lib/commons-lang-2.4.jar:/usr/share/cassandra/lib/compress-lzf-0.8.4.jar:/usr/share/cassandra/lib/concurrentlinkedhashmap-lru-1.3.jar:/usr/share/cassandra/lib/guava-r08.jar:/usr/share/cassandra/lib/high-scale-lib-1.1.2.jar:/usr/share/cassandra/lib/jackson-core-asl-1.9.2.jar:/usr/share/cassandra/lib/jackson-mapper-asl-1.9.2.jar:/usr/share/cassandra/lib/jamm-0.2.5.jar:/usr/share/cassandra/lib/jline-0.9.94.jar:/usr/share/cassandra/lib/json-simple-1.1.jar:/usr/share/cassandra/lib/libthrift-0.7.0.jar:/usr/share/cassandra/lib/log4j-1.2.16.jar:/usr/share/cassandra/lib/metrics-core-2.0.3.jar:/usr/share/cassandra/lib/servlet-api-2.5-20081211.jar:/usr/share/cassandra/lib/slf4j-api-1.6.1.jar:/usr/share/cassandra/lib/slf4j-log4j12-1.6.1.jar:/usr/share/cassandra/lib/snakeyaml-1.6.jar:/usr/share/cassandra/lib/snappy-java-1.0.4.1.jar:/usr/share/cassandra/lib/snaptree-0.1.jar:/usr/share/cassandra/apache-cassandra-1.1.7.jar:/usr/share/cassandra/apache-cassandra-thrift-1.1.7.jar:/usr/share/cassandra/apache-cassandra.jar:/usr/share/cassandra/stress.jar:/usr/share/java/jna.jar:/etc/cassandra:/usr/share/java/commons-daemon.jar:/usr/share/cassandra/lib/jamm-0.2.5.jar
 INFO [main] 2012-12-28 18:45:10,045 CLibrary.java (line 111) JNA mlockall
successful
 INFO [main] 2012-12-28 18:45:10,055 DatabaseDescriptor.java (line 123)
Loading settings from file:/etc/cassandra/cassandra.yaml
 INFO [main] 2012-12-28 18:45:10,472 DatabaseDescriptor.java (line 182)
DiskAccessMode 'auto' determined to be mmap, indexAccessMode is mmap
 INFO [main] 2012-12-28 18:45:11,055 DatabaseDescriptor.java (line 246)
Global memtable threshold is enabled at 272MB
 INFO [main] 2012-12-28 18:45:11,107 Ec2Snitch.java (line 63) EC2Snitch
using region: us-east, zone: 1a.
 INFO [main] 2012-12-28 18:45:11,972 CacheService.java (line 96)
Initializing key cache with capacity of 40 MBs.
 INFO [main] 2012-12-28 18:45:11,985 CacheService.java (line 107)
Scheduling key cache save to each 14400 seconds (going to save all keys).
 INFO [main] 2012-12-28 18:45:11,987 CacheService.java (line 121)
Initializing row cache with capacity of 0 MBs and provider
org.apache.cassandra.cache.SerializingCacheProvider
 INFO [main] 2012-12-28 18:45:12,035 CacheService.java (line 133)
Scheduling row cache save to each 0 seconds (going to save all keys).
 INFO [main] 2012-12-28 18:45:12,413 DatabaseDescriptor.java (line 509)
Couldn't detect any schema definitions in local storage.
 INFO [main] 2012-12-28 18:45:12,413 DatabaseDescriptor.java (line 512)
Found table data in data directories. Consider using the CLI to define your
schema.
 INFO [main] 2012-12-28 18:45:12,468 CommitLog.java (line 124) No commitlog
files found; skipping replay
 INFO [main] 2012-12-28 18:45:12,518 StorageService.java (line 424)
Cassandra version: 1.1.7
 INFO [main] 2012-12-28 18:45:12,518 StorageService.java (line 425) Thrift
API version: 19.33.0
 INFO [main] 2012-12-28 18:45:12,554 StorageService.java (line 426) CQL
supported versions: 2.0.0,3.0.0-beta1 (default: 2.0.0)
 INFO [main] 2012-12-28 18:45:12,643 StorageService.java (line 456) Loading
persisted ring state
 INFO [main] 2012-12-28 18:45:12,646 StorageService.java (line 537)
Starting up server gossip
 INFO [main] 2012-12-28 18:45:12,661 ColumnFamilyStore.java (line 659)
Enqueuing flush of Memtable-LocationInfo@157438507(126/157 serialized/live
bytes, 3 ops)
 INFO [FlushWriter:1] 2012-12-28 18:45:12,661 Memtable.java (line 264)
Writing Memtable-LocationInfo@157438507(126/157 serialized/live bytes, 3
ops)
 INFO [FlushWriter:1] 2012-12-28 18:45:12,744 Memtable.java (line 305)
Completed flushing
/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-1-Data.db
(234 bytes) for commitlog position ReplayPosition(segmentId=1356720312385,
position=586)
 INFO [main] 2012-12-28 18:45:12,756 Ec2Snitch.java (line 113) Ec2Snitch
adding ApplicationState ec2region=us-east ec2zone=1a
 INFO [main] 2012-12-28 18:45:12,792 MessagingService.java (line 284)
Starting Messaging Service on port 7000
 INFO [main] 2012-12-28 18:45:12,803 StorageService.java (line 775)
JOINING: waiting for ring information
 INFO [GossipStage:1] 2012-12-28 18:45:12,932 Gossiper.java (line 851) Node
/10.125.0.17 is now part of the cluster
 INFO [GossipStage:1] 2012-12-28 18:45:12,932 Gossiper.java (line 817)
InetAddress /10.125.0.17 is now UP
 INFO [GossipStage:1] 2012-12-28 18:45:12,936 ColumnFamilyStore.java (line
659) Enqueuing flush of Memtable-LocationInfo@1281435610(52/65
serialized/live bytes, 2 ops)
 INFO [FlushWriter:1] 2012-12-28 18:45:12,937 Memtable.java (line 264)
Writing Memtable-LocationInfo@1281435610(52/65 serialized/live bytes, 2 ops)
 INFO [FlushWriter:1] 2012-12-28 18:45:12,946 Memtable.java (line 305)
Completed flushing
/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-2-Data.db
(165 bytes) for commitlog position ReplayPosition(segmentId=1356720312385,
position=769)
 INFO [main] 2012-12-28 18:45:42,815 StorageService.java (line 775)
JOINING: schema complete, ready to bootstrap
 INFO [main] 2012-12-28 18:45:42,816 StorageService.java (line 775)
JOINING: getting bootstrap token
 INFO [main] 2012-12-28 18:45:42,836 BootStrapper.java (line 128) New token
will be 58390160951331053490088942307836377318 to assume load from /
10.125.0.17
 INFO [main] 2012-12-28 18:45:42,838 ColumnFamilyStore.java (line 659)
Enqueuing flush of Memtable-LocationInfo@617013740(36/45 serialized/live
bytes, 1 ops)
 INFO [FlushWriter:1] 2012-12-28 18:45:42,838 Memtable.java (line 264)
Writing Memtable-LocationInfo@617013740(36/45 serialized/live bytes, 1 ops)
 INFO [FlushWriter:1] 2012-12-28 18:45:42,843 Memtable.java (line 305)
Completed flushing
/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-3-Data.db
(87 bytes) for commitlog position ReplayPosition(segmentId=1356720312385,
position=865)
 INFO [main] 2012-12-28 18:45:42,845 StorageService.java (line 775)
JOINING: sleeping 30000 ms for pending range setup
 INFO [main] 2012-12-28 18:46:12,845 StorageService.java (line 775)
JOINING: Starting to bootstrap...
 INFO [main] 2012-12-28 18:46:12,862 ColumnFamilyStore.java (line 659)
Enqueuing flush of Memtable-LocationInfo@1563763559(53/66 serialized/live
bytes, 2 ops)
 INFO [FlushWriter:1] 2012-12-28 18:46:12,863 Memtable.java (line 264)
Writing Memtable-LocationInfo@1563763559(53/66 serialized/live bytes, 2 ops)
 INFO [FlushWriter:1] 2012-12-28 18:46:12,869 Memtable.java (line 305)
Completed flushing
/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-4-Data.db
(163 bytes) for commitlog position ReplayPosition(segmentId=1356720312385,
position=1046)
 INFO [main] 2012-12-28 18:46:12,910 StorageService.java (line 1120) Node /
10.125.0.6 state jump to normal
 INFO [main] 2012-12-28 18:46:12,911 StorageService.java (line 688)
Bootstrap/Replace/Move completed! Now serving reads.
 INFO [CompactionExecutor:1] 2012-12-28 18:46:12,955 CompactionTask.java
(line 109) Compacting
[SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-4-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-1-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-2-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-3-Data.db')]
 INFO [main] 2012-12-28 18:46:13,017 CassandraDaemon.java (line 124)
Binding thrift service to /0.0.0.0:9160
 INFO [main] 2012-12-28 18:46:13,021 CassandraDaemon.java (line 133) Using
TFastFramedTransport with a max frame size of 15728640 bytes.
 INFO [main] 2012-12-28 18:46:13,053 CassandraDaemon.java (line 160) Using
synchronous/threadpool thrift server on /0.0.0.0 : 9160
 INFO [CompactionExecutor:1] 2012-12-28 18:46:13,057 CompactionTask.java
(line 221) Compacted to
[/var/lib/cassandra/data/system/LocationInfo/system-LocationInfo-hf-5-Data.db,].
649 to 435 (~67% of original) bytes for 4 keys at 0.004148MB/s.  Time:
100ms.
 INFO [Thread-5] 2012-12-28 18:46:13,060 CassandraDaemon.java (line 212)
Listening for thrift clients...
ERROR [MutationStage:33] 2012-12-28 18:48:40,085
RowMutationVerbHandler.java (line 61) Error in row mutation
org.apache.cassandra.db.UnknownColumnFamilyException: Couldn't find
cfId=1000
    at
org.apache.cassandra.db.ColumnFamilySerializer.deserialize(ColumnFamilySerializer.java:126)
    at
org.apache.cassandra.db.RowMutation$RowMutationSerializer.deserialize(RowMutation.java:439)
    at
org.apache.cassandra.db.RowMutation$RowMutationSerializer.deserialize(RowMutation.java:447)
    at org.apache.cassandra.db.RowMutation.fromBytes(RowMutation.java:395)
    at
org.apache.cassandra.db.RowMutationVerbHandler.doVerb(RowMutationVerbHandler.java:42)
    at
org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:59)
    at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:679)
ERROR [MutationStage:34] 2012-12-28 18:48:40,609
RowMutationVerbHandler.java (line 61) Error in row mutation
org.apache.cassandra.db.UnknownColumnFamilyException: Couldn't find
cfId=1000
    at
org.apache.cassandra.db.ColumnFamilySerializer.deserialize(ColumnFamilySerializer.java:126)
    at
org.apache.cassandra.db.RowMutation$RowMutationSerializer.deserialize(RowMutation.java:439)
    at
org.apache.cassandra.db.RowMutation$RowMutationSerializer.deserialize(RowMutation.java:447)
    at org.apache.cassandra.db.RowMutation.fromBytes(RowMutation.java:395)
    at
org.apache.cassandra.db.RowMutationVerbHandler.doVerb(RowMutationVerbHandler.java:42)
    at
org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:59)
    at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:679)
ERROR [MutationStage:35] 2012-12-28 18:48:41,154
RowMutationVerbHandler.java (line 61) Error in row mutation
org.apache.cassandra.db.UnknownColumnFamilyException: Couldn't find
cfId=1000
    at
org.apache.cassandra.db.ColumnFamilySerializer.deserialize(ColumnFamilySerializer.java:126)
    at
org.apache.cassandra.db.RowMutation$RowMutationSerializer.deserialize(RowMutation.java:439)
    at
org.apache.cassandra.db.RowMutation$RowMutationSerializer.deserialize(RowMutation.java:447)
    at org.apache.cassandra.db.RowMutation.fromBytes(RowMutation.java:395)
    at
org.apache.cassandra.db.RowMutationVerbHandler.doVerb(RowMutationVerbHandler.java:42)
    at
org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:59)
    at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:679)