[CASSANDRA-8387] Schema inconsistency (cached vs schema_columnfamilies)

• Type: Bug
• Status: Resolved
• Priority: Normal
• Resolution: Not A Problem

Environment

C* 2.1.1 3-node cluster

• Severity: Normal
• Assignee: Unassigned
• Reporter: Marcus Olsson
• Created: 28/Nov/14 08:48
• Updated: 16/Apr/19 09:31
• Resolved: 31/Mar/15 14:40

Description

While running some tests on a 3-node cluster running C* 2.1.1 we encountered a problem creating the same table schema twice(on different nodes). One thing to note is that one of the nodes clock was ~4 seconds behind the others, but I don't think that's the problem since the exception was reproduced here aswell: http://www.mail-archive.com/[e-mail]/msg39560.html.

While running the same create table statement more than once(on different clients) the logs outputted this on one of the nodes:

(node x.x.x.1):
2014-11-25T16:11:44.651+0100  INFO [SharedPool-Worker-2] MigrationManager.java:248 Create new ColumnFamily: org.apache.cassandra.config.CFMetaData@45c290de[cfId=5e334b40-74b5-11e4-b1b6-017ad0689f5d,ksName=test,cfName=test,cfType=Standard,comparator=org.apache.cassandra.db.marshal.UTF8Type,comment=,readRepairChance=0.0,dcLocalReadRepairChance=0.1,gcGraceSeconds=864000,defaultValidator=org.apache.cassandra.db.marshal.BytesType,keyValidator=org.apache.cassandra.db.marshal.UTF8Type,minCompactionThreshold=4,maxCompactionThreshold=32,columnMetadata=[ColumnDefinition{name=id, type=org.apache.cassandra.db.marshal.UTF8Type, kind=CLUSTERING_COLUMN, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=key, type=org.apache.cassandra.db.marshal.UTF8Type, kind=PARTITION_KEY, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=value, type=org.apache.cassandra.db.marshal.BytesType, kind=COMPACT_VALUE, componentIndex=null, indexName=null, indexType=null}],compactionStrategyClass=class org.apache.cassandra.db.compaction.SizeTieredCompactionStrategy,compactionStrategyOptions={},compressionParameters={sstable_compression=org.apache.cassandra.io.compress.LZ4Compressor},bloomFilterFpChance=0.01,memtableFlushPeriod=0,caching={"keys":"ALL", "rows_per_partition":"NONE"},defaultTimeToLive=0,minIndexInterval=128,maxIndexInterval=2048,speculativeRetry=99.0PERCENTILE,droppedColumns={},triggers=[],isDense=true]

...

2014-11-25T16:11:44.667+0100  INFO [MigrationStage:1] DefsTables.java:373 Loading org.apache.cassandra.config.CFMetaData@40a1ee90[cfId=5bc7c980-74b5-11e4-9131-d9b94a3d8927,ksName=test,cfName=test,cfType=Standard,comparator=org.apache.cassandra.db.marshal.UTF8Type,comment=,readRepairChance=0.0,dcLocalReadRepairChance=0.1,gcGraceSeconds=864000,defaultValidator=org.apache.cassandra.db.marshal.BytesType,keyValidator=org.apache.cassandra.db.marshal.UTF8Type,minCompactionThreshold=4,maxCompactionThreshold=32,columnMetadata=[ColumnDefinition{name=id, type=org.apache.cassandra.db.marshal.UTF8Type, kind=CLUSTERING_COLUMN, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=key, type=org.apache.cassandra.db.marshal.UTF8Type, kind=PARTITION_KEY, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=value, type=org.apache.cassandra.db.marshal.BytesType, kind=COMPACT_VALUE, componentIndex=null, indexName=null, indexType=null}],compactionStrategyClass=class org.apache.cassandra.db.compaction.SizeTieredCompactionStrategy,compactionStrategyOptions={},compressionParameters={sstable_compression=org.apache.cassandra.io.compress.LZ4Compressor},bloomFilterFpChance=0.01,memtableFlushPeriod=0,caching={"keys":"ALL", "rows_per_partition":"NONE"},defaultTimeToLive=0,minIndexInterval=128,maxIndexInterval=2048,speculativeRetry=99.0PERCENTILE,droppedColumns={},triggers=[],isDense=true]

...

java.lang.RuntimeException: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1171) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.updateColumnFamily(DefsTables.java:422) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeColumnFamilies(DefsTables.java:295) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchemaInternal(DefsTables.java:194) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchema(DefsTables.java:166) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.service.MigrationManager$2.runMayThrow(MigrationManager.java:393) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_51]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_51]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]
Caused by: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.validateCompatility(CFMetaData.java:1254) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.apply(CFMetaData.java:1186) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1167) ~[apache-cassandra-2.1.1.jar:2.1.1]
        ... 11 common frames omitted
2014-11-25T16:11:44.859+0100 ERROR [SharedPool-Worker-2] ErrorMessage.java:243 Unexpected exception during request
java.lang.RuntimeException: java.util.concurrent.ExecutionException: java.lang.RuntimeException: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-
b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.utils.FBUtilities.waitOnFuture(FBUtilities.java:397) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.service.MigrationManager.announce(MigrationManager.java:374) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.service.MigrationManager.announceNewColumnFamily(MigrationManager.java:249) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.cql3.statements.CreateTableStatement.announceMigration(CreateTableStatement.java:114) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.cql3.statements.SchemaAlteringStatement.execute(SchemaAlteringStatement.java:80) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.cql3.QueryProcessor.processStatement(QueryProcessor.java:226) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.cql3.QueryProcessor.processPrepared(QueryProcessor.java:481) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.transport.messages.ExecuteMessage.execute(ExecuteMessage.java:133) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.transport.Message$Dispatcher.channelRead0(Message.java:439) [apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.transport.Message$Dispatcher.channelRead0(Message.java:335) [apache-cassandra-2.1.1.jar:2.1.1]
        at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-all-4.0.23.Final.jar:4.0.23.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:333) [netty-all-4.0.23.Final.jar:4.0.23.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$700(AbstractChannelHandlerContext.java:32) [netty-all-4.0.23.Final.jar:4.0.23.Final]
        at io.netty.channel.AbstractChannelHandlerContext$8.run(AbstractChannelHandlerContext.java:324) [netty-all-4.0.23.Final.jar:4.0.23.Final]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_51]
        at org.apache.cassandra.concurrent.AbstractTracingAwareExecutorService$FutureTask.run(AbstractTracingAwareExecutorService.java:164) [apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:105) [apache-cassandra-2.1.1.jar:2.1.1]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]
Caused by: java.util.concurrent.ExecutionException: java.lang.RuntimeException: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d
; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[na:1.7.0_51]
        at java.util.concurrent.FutureTask.get(FutureTask.java:188) ~[na:1.7.0_51]
        at org.apache.cassandra.utils.FBUtilities.waitOnFuture(FBUtilities.java:393) ~[apache-cassandra-2.1.1.jar:2.1.1]
        ... 17 common frames omitted
Caused by: java.lang.RuntimeException: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1171) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.updateColumnFamily(DefsTables.java:422) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeColumnFamilies(DefsTables.java:295) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchemaInternal(DefsTables.java:194) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchema(DefsTables.java:166) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.service.MigrationManager$2.runMayThrow(MigrationManager.java:393) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_51]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) ~[na:1.7.0_51]
        ... 1 common frames omitted
Caused by: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.validateCompatility(CFMetaData.java:1254) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.apply(CFMetaData.java:1186) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1167) ~[apache-cassandra-2.1.1.jar:2.1.1]
        ... 11 common frames omitted

In my understanding this means that it first created the table(with UUID 5e..) and then got a schema update from another node with UUID 5b.. .

And the node who created the 5b.. table had this:

(node x.x.x.2):
2014-11-25T16:11:40.580+0100  INFO [SharedPool-Worker-1] MigrationManager.java:248 Create new ColumnFamily: org.apache.cassandra.config.CFMetaData@225c1975[cfId=5bc7c980-74b5-11e4-9131-d9b94a3d8927,ksName=test,cfName=test,cfType=Standard,comparator=org.apache.cassandra.db.marshal.UTF8Type,comment=,readRepairChance=0.0,dcLocalReadRepairChance=0.1,gcGraceSeconds=864000,defaultValidator=org.apache.cassandra.db.marshal.BytesType,keyValidator=org.apache.cassandra.db.marshal.UTF8Type,minCompactionThreshold=4,maxCompactionThreshold=32,columnMetadata=[ColumnDefinition{name=id, type=org.apache.cassandra.db.marshal.UTF8Type, kind=CLUSTERING_COLUMN, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=key, type=org.apache.cassandra.db.marshal.UTF8Type, kind=PARTITION_KEY, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=value, type=org.apache.cassandra.db.marshal.BytesType, kind=COMPACT_VALUE, componentIndex=null, indexName=null, indexType=null}],compactionStrategyClass=class org.apache.cassandra.db.compaction.SizeTieredCompactionStrategy,compactionStrategyOptions={},compressionParameters={sstable_compression=org.apache.cassandra.io.compress.LZ4Compressor},bloomFilterFpChance=0.01,memtableFlushPeriod=0,caching={"keys":"ALL", "rows_per_partition":"NONE"},defaultTimeToLive=0,minIndexInterval=128,maxIndexInterval=2048,speculativeRetry=99.0PERCENTILE,droppedColumns={},triggers=[],isDense=true]

...

java.lang.RuntimeException: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1171) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.updateColumnFamily(DefsTables.java:422) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeColumnFamilies(DefsTables.java:295) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchemaInternal(DefsTables.java:194) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchema(DefsTables.java:166) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefinitionsUpdateVerbHandler$1.runMayThrow(DefinitionsUpdateVerbHandler.java:49) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_51]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_51]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]
Caused by: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.validateCompatility(CFMetaData.java:1254) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.apply(CFMetaData.java:1186) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1167) ~[apache-cassandra-2.1.1.jar:2.1.1]
        ... 11 common frames omitted

And the last node had this:

(node x.x.x.3):
2014-11-25T16:11:44.363+0100  INFO [MigrationStage:1] DefsTables.java:373 Loading org.apache.cassandra.config.CFMetaData@767512bf[cfId=5bc7c980-74b5-11e4-9131-d9b94a3d8927,ksName=test,cfName=test,cfType=Standard,comparator=org.apache.cassandra.db.marshal.UTF8Type,comment=,readRepairChance=0.0,dcLocalReadRepairChance=0.1,gcGraceSeconds=864000,defaultValidator=org.apache.cassandra.db.marshal.BytesType,keyValidator=org.apache.cassandra.db.marshal.UTF8Type,minCompactionThreshold=4,maxCompactionThreshold=32,columnMetadata=[ColumnDefinition{name=id, type=org.apache.cassandra.db.marshal.UTF8Type, kind=CLUSTERING_COLUMN, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=key, type=org.apache.cassandra.db.marshal.UTF8Type, kind=PARTITION_KEY, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=value, type=org.apache.cassandra.db.marshal.BytesType, kind=COMPACT_VALUE, componentIndex=null, indexName=null, indexType=null}],compactionStrategyClass=class org.apache.cassandra.db.compaction.SizeTieredCompactionStrategy,compactionStrategyOptions={},compressionParameters={sstable_compression=org.apache.cassandra.io.compress.LZ4Compressor},bloomFilterFpChance=0.01,memtableFlushPeriod=0,caching={"keys":"ALL", "rows_per_partition":"NONE"},defaultTimeToLive=0,minIndexInterval=128,maxIndexInterval=2048,speculativeRetry=99.0PERCENTILE,droppedColumns={},triggers=[],isDense=true]

...

java.lang.RuntimeException: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1171) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.updateColumnFamily(DefsTables.java:422) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeColumnFamilies(DefsTables.java:295) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchemaInternal(DefsTables.java:194) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefsTables.mergeSchema(DefsTables.java:166) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.db.DefinitionsUpdateVerbHandler$1.runMayThrow(DefinitionsUpdateVerbHandler.java:49) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_51]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_51]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]
Caused by: org.apache.cassandra.exceptions.ConfigurationException: Column family ID mismatch (found 5e334b40-74b5-11e4-b1b6-017ad0689f5d; expected 5bc7c980-74b5-11e4-9131-d9b94a3d8927)
        at org.apache.cassandra.config.CFMetaData.validateCompatility(CFMetaData.java:1254) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.apply(CFMetaData.java:1186) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.config.CFMetaData.reload(CFMetaData.java:1167) ~[apache-cassandra-2.1.1.jar:2.1.1]
        ... 11 common frames omitted

Not a problem at all, since they all seemed to agree that 5b.. was the schema to go with and everything went fine with inserting data into the table. The data directory contained the 5b.. directory and not 5e.. (on all nodes). The problem occured later when node x.x.x.3 was restarted it created the directory test/test-5e.. in the data directory. When performing a repair on the node it gave these kinds of exceptions:

(node x.x.x.3):
2014-11-25T16:21:31.726+0100  WARN [STREAM-IN-/x.x.x.2] StreamSession.java:590 [Stream #bc054793-74b6-11e4-baf6-fbb25862655d] Retrying for following error
java.io.IOException: CF 5bc7c980-74b5-11e4-9131-d9b94a3d8927 was dropped during streaming
        at org.apache.cassandra.streaming.compress.CompressedStreamReader.read(CompressedStreamReader.java:71) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:48) [apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:38) [apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:55) [apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:245) [apache-cassandra-2.1.1.jar:2.1.1]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]

...

2014-11-25T16:21:31.726+0100 ERROR [STREAM-IN-/x.x.x.2] StreamSession.java:470 [Stream #bc054793-74b6-11e4-baf6-fbb25862655d] Streaming error occurred
java.lang.IllegalArgumentException: Unknown type 0
        at org.apache.cassandra.streaming.messages.StreamMessage$Type.get(StreamMessage.java:89) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:54) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:245) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]

...

2014-11-25T16:21:31.738+0100 ERROR [AntiEntropySessions:1] RepairSession.java:303 [repair #bbf34630-74b6-11e4-baf6-fbb25862655d] session completed with the following error
org.apache.cassandra.exceptions.RepairException: [repair #bbf34630-74b6-11e4-baf6-fbb25862655d on test/test, (3708140006327119811,3721360916800446611]] Sync failed between /x.x.x.3 and
 /x.x.x.2
        at org.apache.cassandra.repair.RepairSession.syncComplete(RepairSession.java:223) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.service.ActiveRepairService.handleMessage(ActiveRepairService.java:389) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.repair.RepairMessageVerbHandler.doVerb(RepairMessageVerbHandler.java:126) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:62) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_51]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_51]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]

And the other nodes had exceptions like:

(node x.x.x.2)
2014-11-25T16:21:28.145+0100 ERROR [STREAM-OUT-/x.x.x.3] StreamSession.java:470 [Stream #bc309d50-74b6-11e4-baf6-fbb25862655d] Streaming error occurred
java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.7.0_51]
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.7.0_51]
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.7.0_51]
        at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.7.0_51]
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:487) ~[na:1.7.0_51]
        at java.nio.channels.Channels.writeFullyImpl(Channels.java:78) ~[na:1.7.0_51]
        at java.nio.channels.Channels.writeFully(Channels.java:98) ~[na:1.7.0_51]
        at java.nio.channels.Channels.access$000(Channels.java:61) ~[na:1.7.0_51]
        at java.nio.channels.Channels$1.write(Channels.java:174) ~[na:1.7.0_51]
        at java.io.OutputStream.write(OutputStream.java:75) ~[na:1.7.0_51]
        at java.nio.channels.Channels$1.write(Channels.java:155) ~[na:1.7.0_51]
        at org.apache.cassandra.io.util.DataOutputStreamPlus.write(DataOutputStreamPlus.java:45) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.io.util.AbstractDataOutput.writeLong(AbstractDataOutput.java:232) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.io.compress.CompressionMetadata$ChunkSerializer.serialize(CompressionMetadata.java:406) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.io.compress.CompressionMetadata$ChunkSerializer.serialize(CompressionMetadata.java:402) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.compress.CompressionInfo$CompressionInfoSerializer.serialize(CompressionInfo.java:60) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.compress.CompressionInfo$CompressionInfoSerializer.serialize(CompressionInfo.java:47) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.messages.FileMessageHeader$FileMessageHeaderSerializer.serialize(FileMessageHeader.java:135) ~[apache-cassandra-2.1.1.jar:2.1.1]
        at org.apache.cassandra.streaming.messages.FileMessageHeader$FileMessageHeaderSerializer.serialize(FileMessageHeader.java:120) ~[apache-cassandra-2.1.1.jar:2.1.1]

In System.schema_columnfamilies the id for test.test is 5e.. on all nodes, but the nodes that hadn't restarted still used the 5b.. id for the table (atleast in the data directory, probably a cached id).

The problem seems to be that the schema change for 5e.. is rejected on all nodes (java.lang.RuntimeException: org.apache.cassandra.exceptions.ConfigurationException thrown), while the mutation for it still gets applied in schema_columnfamilies.

Issue Links

• relates to: CASSANDRA-5025 Schema push/pull race