You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Jonathan Ellis (JIRA)" <ji...@apache.org> on 2013/01/26 00:25:13 UTC
[jira] [Commented] (CASSANDRA-3857) AIOOB during bootstrap causes
insta-join as Normal in ring, serving bad reads
[ https://issues.apache.org/jira/browse/CASSANDRA-3857?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13563155#comment-13563155 ]
Jonathan Ellis commented on CASSANDRA-3857:
-------------------------------------------
TokenMetadata was rewritten for vnodes, suspect this is fixed.
> AIOOB during bootstrap causes insta-join as Normal in ring, serving bad reads
> -----------------------------------------------------------------------------
>
> Key: CASSANDRA-3857
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3857
> Project: Cassandra
> Issue Type: Bug
> Reporter: Peter Schuller
> Assignee: Peter Schuller
>
> The reason I realized there was something still fishy in CASSANDRA-3832 was that I thought I had seen nodes just join instantly into Normal state earlier on trunk. When I tried to re-produce that I got what I'm mentioning in CASSANDRA-3832. While investigating *THAT* I now triggered what I believe to be insta-join again. The node that was bootstrapping died with the below exception during start-up, automatically re-started (due to monit in this case) and then joined the ring. I'm pretty sure it didn't go into Joining first, I *just* managed to catch the "watch" I had going on a nodetool | grep on another node. Additionally, looking at the log below I see no evidence of waiting for ring delay which is should as part of boot-strap, nor do I see "Starting to bootstrap ... " logged.
> A quick look at the code makes me confused how this is possible given that the bootstrap flag is set *after* the point int he code where we bailed with the exception.
> As for the exception, I've seen something like this when investigating CASSANDRA-3831 and CASSANDRA-3417, but I never got to the bottom of it believing it had to do with the lack of synchronization. I look back now and it seems my trunk is one that doesn't have the latest patch that I submitted to CASSANDRA-3417, but I haven't looked at it in detail to determine whether it fixes it. In any case, the insta-join is a problem.
> {code}
> INFO [main] 2012-02-06 03:59:34,059 StorageService.java (line 728) JOINING: schema complete, ready to bootstrap
> INFO [main] 2012-02-06 03:59:34,059 StorageService.java (line 728) JOINING: getting bootstrap token
> ERROR [main] 2012-02-06 03:59:34,062 AbstractCassandraDaemon.java (line 370) Exception encountered during startup
> java.lang.ArrayIndexOutOfBoundsException: -2
> at java.util.ArrayList.get(ArrayList.java:324)
> at org.apache.cassandra.locator.TokenMetadata.getPredecessor(TokenMetadata.java:521)
> at org.apache.cassandra.locator.TokenMetadata.getPrimaryRangeFor(TokenMetadata.java:463)
> at org.apache.cassandra.locator.TokenMetadata.pendingRangeChanges(TokenMetadata.java:111)
> at org.apache.cassandra.dht.BootStrapper$1.compare(BootStrapper.java:144)
> at org.apache.cassandra.dht.BootStrapper$1.compare(BootStrapper.java:141)
> at java.util.Arrays.mergeSort(Arrays.java:1270)
> at java.util.Arrays.mergeSort(Arrays.java:1281)
> at java.util.Arrays.mergeSort(Arrays.java:1281)
> at java.util.Arrays.mergeSort(Arrays.java:1281)
> at java.util.Arrays.mergeSort(Arrays.java:1281)
> at java.util.Arrays.mergeSort(Arrays.java:1281)
> at java.util.Arrays.sort(Arrays.java:1210)
> at java.util.Collections.sort(Collections.java:159)
> at org.apache.cassandra.dht.BootStrapper.getBootstrapSource(BootStrapper.java:140)
> at org.apache.cassandra.dht.BootStrapper.getBalancedToken(BootStrapper.java:116)
> at org.apache.cassandra.dht.BootStrapper.getBootstrapToken(BootStrapper.java:111)
> at org.apache.cassandra.service.StorageService.joinTokenRing(StorageService.java:585)
> at org.apache.cassandra.service.StorageService.initServer(StorageService.java:502)
> at org.apache.cassandra.service.StorageService.initServer(StorageService.java:411)
> at org.apache.cassandra.service.AbstractCassandraDaemon.setup(AbstractCassandraDaemon.java:231)
> at org.apache.cassandra.service.AbstractCassandraDaemon.activate(AbstractCassandraDaemon.java:353)
> at org.apache.cassandra.thrift.CassandraDaemon.main(CassandraDaemon.java:107)
> INFO [StorageServiceShutdownHook] 2012-02-06 03:59:34,065 MessagingService.java (line 541) Waiting for messaging service to quiesce
> INFO [ACCEPT-/10.40.33.128] 2012-02-06 03:59:34,065 MessagingService.java (line 697) MessagingService shutting down server thread.
> INFO [main] 2012-02-06 03:59:39,760 AbstractCassandraDaemon.java (line 100) Logging initialized
> INFO [main] 2012-02-06 03:59:39,763 AbstractCassandraDaemon.java (line 121) JVM vendor/version: Java HotSpot(TM) 64-Bit Server VM/1.6.0_24
> INFO [main] 2012-02-06 03:59:39,764 AbstractCassandraDaemon.java (line 122) Heap size: 12845645824/12845645824
> INFO [main] 2012-02-06 03:59:39,764 AbstractCassandraDaemon.java (line 123) Classpath: /usr/local/cassandra/current/conf/atla/cassandra.prod.cuckoo:/usr/local/cassandra/current/vendor/cassandra/build/classes:/usr/local/cassandra/current/vendor/cassandra/lib/antlr-3.2.jar:/usr/local/cassandra/current/vendor/cassandra/lib/apache-cassandra-clientutil-twttr-cassandra-trunk-upstream-but-buildable-log-calc-pending-6.jar:/usr/local/cassandra/current/vendor/cassandra/lib/apache-cassandra-thrift-twttr-cassandra-trunk-upstream-but-buildable-log-calc-pending-6.jar:/usr/local/cassandra/current/vendor/cassandra/lib/apache-cassandra-twttr-cassandra-trunk-upstream-but-buildable-log-calc-pending-6.jar:/usr/local/cassandra/current/vendor/cassandra/lib/avro-1.4.0-fixes.jar:/usr/local/cassandra/current/vendor/cassandra/lib/avro-1.4.0-sources-fixes.jar:/usr/local/cassandra/current/vendor/cassandra/lib/commons-cli-1.1.jar:/usr/local/cassandra/current/vendor/cassandra/lib/commons-codec-1.2.jar:/usr/local/cassandra/current/vendor/cassandra/lib/commons-lang-2.4.jar:/usr/local/cassandra/current/vendor/cassandra/lib/compress-lzf-0.8.4.jar:/usr/local/cassandra/current/vendor/cassandra/lib/concurrentlinkedhashmap-lru-1.2.jar:/usr/local/cassandra/current/vendor/cassandra/lib/guava-r08.jar:/usr/local/cassandra/current/vendor/cassandra/lib/high-scale-lib-1.1.2.jar:/usr/local/cassandra/current/vendor/cassandra/lib/jackson-core-asl-1.9.2.jar:/usr/local/cassandra/current/vendor/cassandra/lib/jackson-mapper-asl-1.9.2.jar:/usr/local/cassandra/current/vendor/cassandra/lib/jamm-0.2.5.jar:/usr/local/cassandra/current/vendor/cassandra/lib/jline-0.9.94.jar:/usr/local/cassandra/current/vendor/cassandra/lib/json-simple-1.1.jar:/usr/local/cassandra/current/vendor/cassandra/lib/libthrift-0.7.0.jar:/usr/local/cassandra/current/vendor/cassandra/lib/log4j-1.2.16.jar:/usr/local/cassandra/current/vendor/cassandra/lib/servlet-api-2.5-20081211.jar:/usr/local/cassandra/current/vendor/cassandra/lib/slf4j-api-1.6.1.jar:/usr/local/cassandra/current/vendor/cassandra/lib/slf4j-log4j12-1.6.1.jar:/usr/local/cassandra/current/vendor/cassandra/lib/snakeyaml-1.6.jar:/usr/local/cassandra/current/vendor/cassandra/lib/snappy-java-1.0.4.1.jar:/usr/local/cassandra/current/vendor/cassandra/lib/snaptree-0.1-SNAPSHOT.jar:/usr/local/cassandra/current/vendor/cassandra/build/lib/jars/*.jar:/usr/local/cassandra/current/vendor/cassandra/build/lib/twitter-jars/*.jar:/usr/local/cassandra/current/vendor/cassandra/lib/twitter-jars/*.jar
> INFO [main] 2012-02-06 03:59:39,765 CLibrary.java (line 66) JNA not found. Native methods will be disabled.
> INFO [main] 2012-02-06 03:59:39,772 DatabaseDescriptor.java (line 127) Loading settings from file:/usr/local/cassandra/releases/20120206035358/conf/atla/cassandra.prod.cuckoo-upstream-trunk/cassandra.yaml
> INFO [main] 2012-02-06 03:59:39,874 DatabaseDescriptor.java (line 181) DiskAccessMode 'auto' determined to be mmap, indexAccessMode is mmap
> INFO [main] 2012-02-06 03:59:39,884 DatabaseDescriptor.java (line 246) Global memtable threshold is enabled at 4083MB
> INFO [main] 2012-02-06 03:59:39,992 CacheService.java (line 100) Initializing key cache with capacity of 2 MBs.
> INFO [main] 2012-02-06 03:59:40,003 CacheService.java (line 111) Scheduling key cache save to each 14400 seconds (going to save all keys).
> INFO [main] 2012-02-06 03:59:40,004 CacheService.java (line 125) Initializing row cache with capacity of 0 MBs and provider org.apache.cassandra.cache.ConcurrentLinkedHashCacheProvider
> INFO [main] 2012-02-06 03:59:40,006 CacheService.java (line 137) Scheduling row cache save to each 0 seconds (going to save all keys).
> INFO [SSTableBatchOpen:1] 2012-02-06 03:59:40,070 SSTableReader.java (line 156) Opening /data/diskarray/tables/system/schema_columnfamilies/system-schema_columnfamilies-hc-30 (1399 bytes)
> INFO [SSTableBatchOpen:2] 2012-02-06 03:59:40,071 SSTableReader.java (line 156) Opening /data/diskarray/tables/system/schema_columnfamilies/system-schema_columnfamilies-hc-29 (1399 bytes)
> INFO [SSTableBatchOpen:3] 2012-02-06 03:59:40,071 SSTableReader.java (line 156) Opening /data/diskarray/tables/system/schema_columnfamilies/system-schema_columnfamilies-hc-31 (1399 bytes)
> INFO [SSTableBatchOpen:1] 2012-02-06 03:59:40,106 SSTableReader.java (line 156) Opening /data/diskarray/tables/system/schema_keyspaces/system-schema_keyspaces-hc-30 (255 bytes)
> INFO [SSTableBatchOpen:3] 2012-02-06 03:59:40,107 SSTableReader.java (line 156) Opening /data/diskarray/tables/system/schema_keyspaces/system-schema_keyspaces-hc-29 (255 bytes)
> INFO [SSTableBatchOpen:2] 2012-02-06 03:59:40,107 SSTableReader.java (line 156) Opening /data/diskarray/tables/system/schema_keyspaces/system-schema_keyspaces-hc-31 (255 bytes)
> INFO [SSTableBatchOpen:1] 2012-02-06 03:59:40,116 SSTableReader.java (line 156) Opening /data/diskarray/tables/system/LocationInfo/system-LocationInfo-hc-245 (6775 bytes)
> INFO [main] 2012-02-06 03:59:40,391 AbstractCassandraDaemon.java (line 208) completed pre-loading (4 keys) key cache.
> INFO [main] 2012-02-06 03:59:40,504 CommitLog.java (line 142) Replaying /data/disk1/commitlog/CommitLog-650613166587178.log, /data/disk1/commitlog/CommitLog-650613060900385.log
> INFO [main] 2012-02-06 03:59:40,508 CommitLog.java (line 185) Replaying /data/disk1/commitlog/CommitLog-650613166587178.log
> INFO [main] 2012-02-06 03:59:40,509 CommitLog.java (line 339) Finished reading /data/disk1/commitlog/CommitLog-650613166587178.log
> INFO [main] 2012-02-06 03:59:40,509 CommitLog.java (line 185) Replaying /data/disk1/commitlog/CommitLog-650613060900385.log
> INFO [main] 2012-02-06 03:59:40,584 CommitLog.java (line 339) Finished reading /data/disk1/commitlog/CommitLog-650613060900385.log
> INFO [main] 2012-02-06 03:59:40,588 ColumnFamilyStore.java (line 590) Enqueuing flush of Memtable-Versions@275980095(141/176 serialized/live bytes, 3 ops)
> INFO [FlushWriter:1] 2012-02-06 03:59:40,600 Memtable.java (line 252) Writing Memtable-Versions@275980095(141/176 serialized/live bytes, 3 ops)
> INFO [FlushWriter:1] 2012-02-06 03:59:40,618 Memtable.java (line 293) Completed flushing /data/diskarray/tables/system/Versions/system-Versions-hc-1-Data.db (305 bytes)
> INFO [main] 2012-02-06 03:59:40,625 CommitLog.java (line 144) Log replay complete, 3 replayed mutations
> INFO [main] 2012-02-06 03:59:40,637 StorageService.java (line 416) Cassandra version: twttr-cassandra-trunk-upstream-but-buildable-log-calc-pending-6
> INFO [main] 2012-02-06 03:59:40,638 StorageService.java (line 417) Thrift API version: 19.28.0
> INFO [main] 2012-02-06 03:59:40,639 StorageService.java (line 418) CQL supported versions: 2.0.0,3.0.0-beta1 (default: 2.0.0)
> INFO [main] 2012-02-06 03:59:40,639 StorageService.java (line 431) Loading persisted ring state
> INFO [main] 2012-02-06 03:59:40,670 StorageService.java (line 512) Starting up server gossip
> INFO [main] 2012-02-06 03:59:40,676 ColumnFamilyStore.java (line 590) Enqueuing flush of Memtable-LocationInfo@1983702821(29/36 serialized/live bytes, 1 ops)
> INFO [FlushWriter:1] 2012-02-06 03:59:40,676 Memtable.java (line 252) Writing Memtable-LocationInfo@1983702821(29/36 serialized/live bytes, 1 ops)
> INFO [FlushWriter:1] 2012-02-06 03:59:40,683 Memtable.java (line 293) Completed flushing /data/diskarray/tables/system/LocationInfo/system-LocationInfo-hc-246-Data.db (80 bytes)
> INFO [main] 2012-02-06 03:59:40,689 MessagingService.java (line 286) Starting Messaging Service on port 7000
> WARN [main] 2012-02-06 03:59:40,697 StorageService.java (line 619) Generated random token 100588447224685279983438741296967523984. Random tokens will result in an unbalanced ring; see http://wiki.apache.org/cassandra/Operations
> INFO [main] 2012-02-06 03:59:40,697 ColumnFamilyStore.java (line 590) Enqueuing flush of Memtable-LocationInfo@44130647(53/66 serialized/live bytes, 2 ops)
> INFO [FlushWriter:1] 2012-02-06 03:59:40,698 Memtable.java (line 252) Writing Memtable-LocationInfo@44130647(53/66 serialized/live bytes, 2 ops)
> INFO [FlushWriter:1] 2012-02-06 03:59:40,703 Memtable.java (line 293) Completed flushing /data/diskarray/tables/system/LocationInfo/system-LocationInfo-hc-247-Data.db (163 bytes)
> INFO [main] 2012-02-06 03:59:40,705 StorageService.java (line 1049) Node /10.40.33.128 state jump to normal
> INFO [main] 2012-02-06 03:59:40,711 StorageService.java (line 1275) calculate pending ranges called, took 6 ms
> INFO [main] 2012-02-06 03:59:40,711 StorageService.java (line 641) Bootstrap/Replace/Move completed! Now serving reads.
> INFO [main] 2012-02-06 03:59:40,712 Mx4jTool.java (line 72) Will not load MX4J, mx4j-tools.jar is not in the classpath
> INFO [main] 2012-02-06 03:59:40,736 CassandraDaemon.java (line 125) Binding thrift service to localhost/127.0.0.1:9160
> INFO [main] 2012-02-06 03:59:40,738 CassandraDaemon.java (line 134) Using TFastFramedTransport with a max frame size of 15728640 bytes.
> INFO [main] 2012-02-06 03:59:40,740 CassandraDaemon.java (line 161) Using synchronous/threadpool thrift server on localhost/127.0.0.1 : 9160
> INFO [Thread-2] 2012-02-06 03:59:40,741 CassandraDaemon.java (line 213) Listening for thrift clients...
> {code}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira