Schema change issue

[Игорь С]

Hi,

I'm getting table unconfigured/already exists exceptions when some sequenced migration scripts applied to cassandra schema, like drop table A; create table A;.

After some investigation I found out that starting from some point one of the cluster nodes doesn't perform schema changes. 

This is how it looks:

1. Schema change statement executed in my app (see screenshot attached)

2. Result looks normal, statement was routed to the 10.1.1.115, the node where I see this strange behaviour

3. Checking cassandra migration log, looks like statement was applied:

INFO  [SharedPool-Worker-1] 2016-07-01 11:38:52,285 MigrationManager.java:308 - Create new table: org.apache.cassandra.config.CFMetaData@65e7dba0[cfId=628843c0-3f80-11e6-9858-a120c4d78cc6,ksName=xxx,cfName=foo,cfType=Standard,comparator=org.apache.cassandra.db.marshal.CompositeType(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.UUIDType,minCompactionThreshold=4,maxCompactionThreshold=32,columnMetadata=[ColumnDefinition{name=user_id, type=org.apache.cassandra.db.marshal.UUIDType, kind=PARTITION_KEY, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=name, type=org.apache.cassandra.db.marshal.UTF8Type, kind=REGULAR, componentIndex=0, 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=false]

DEBUG [MigrationStage:1] 2016-07-01 11:38:52,360 MigrationManager.java:493 - Gossiping my schema version e1956673-5b49-3b47-8f41-17d668211893

DEBUG [GossipStage:1] 2016-07-01 11:38:52,443 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 11:38:53,417 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 11:38:53,932 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

4. Try to use table created:

vagrant@node3:/var/log/cassandra$ date

Fri Jul  1 11:39:35 UTC 2016

vagrant@node3:/var/log/cassandra$ cqlsh -e " select * from xxx.foo" node3

<stdin>:1:InvalidRequest: code=2200 [Invalid query] message="unconfigured table foo"

This happens with all schema change statements that routed to 10.1.1.115.

When I connected with cqlsh to this node and try the same, it worked:

vagrant@node3:/var/log/cassandra$ cqlsh node3

cqlsh:xxx> CREATE TABLE foo (user_id uuid, name text, PRIMARY KEY (user_id));

cqlsh:xxx>

cqlsh:xxx> select * from foo;

 user_id | name

---------+------

(0 rows)

cqlsh:xxx>

cqlsh:xxx> DROP TABLE foo;

cqlsh:xxx>

cqlsh:xxx> select * from foo;

InvalidRequest: code=2200 [Invalid query] message="unconfigured table foo"

INFO  [SharedPool-Worker-1] 2016-07-01 11:52:28,848 MigrationManager.java:308 - Create new table: org.apache.cassandra.config.CFMetaData@3521aa22[cfId=493de3f0-3f82-11e6-9858-a120c4d78cc6,ksName=xxx,cfName=foo,cfType=Standard,comparator=org.apache.cassandra.db.marshal.CompositeType(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.UUIDType,minCompactionThreshold=4,maxCompactionThreshold=32,columnMetadata=[ColumnDefinition{name=user_id, type=org.apache.cassandra.db.marshal.UUIDType, kind=PARTITION_KEY, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=name, type=org.apache.cassandra.db.marshal.UTF8Type, kind=REGULAR, componentIndex=0, 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=false]

DEBUG [MigrationStage:1] 2016-07-01 11:52:28,968 MigrationManager.java:493 - Gossiping my schema version 67eac9c8-0144-3d78-aaa0-34eb16fcda5c

DEBUG [GossipStage:1] 2016-07-01 11:52:29,432 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 11:52:29,524 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

INFO  [SharedPool-Worker-1] 2016-07-01 11:52:52,689 MigrationManager.java:401 - Drop table 'xxx/foo'

DEBUG [MigrationStage:1] 2016-07-01 11:52:52,975 MigrationManager.java:493 - Gossiping my schema version 0ae78448-da5c-3194-a07e-469f6c010734

DEBUG [GossipStage:1] 2016-07-01 11:52:53,499 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 11:52:54,155 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

Driver version: 3.0.0

Cassandra version: 2.2.4

Cluster deployed locally on three different VM's, nodetool status attached.

Could someone please advice on this,

Thanks,

Igor Sudakov

[Andrew Tolbert]

Hi Igor,

Just so I understand correctly, are you saying that:

1. You executed a schema change in your app (created table foo)
2. node3 (10.1.1.115) logged that it was creating the table (that first log entry was from node3 right, or was it from another node?), but when cqlsh'ing to node 3 you could not effectively query it.
3. However, you could create the table on node3 and after that you were able to query it.

A couple questions:

1. Are all nodes in the cluster at the same schema version?  Does 'nodetool describecluster' only show one schema version for all nodes in the cluster?
2. Are all the nodes at the same C* version?  

I'd imagine at this point its possible all the nodes now show the same schema version, but worth checking anyways.  It would have been interesting to see if the schema versions were not consistent between node3 and the other two nodes after step #1.  Can you reproduce this, or was it a one time occurrence?

It is also possible that after executing a schema change in your app that the schemas were not in agreement yet.   You can use Cluster.getMetadata().checkSchemaAgreement() to have the driver check to see if the schema versions between all nodes in the cluster.  Additionally you can also use ResultSet.getExecutionInfo().isSchemaInAgreement() from the ResultSet returned from your schema query to check if the schema is in agreement after your schema change is made and within the max schema agreement wait time as well.   You can read more about Schema Agreement in our manual for more information on that process.

Thanks,

Andy

[Игорь С]

Hi Andy,

thanks a lot for the quick feedback!

Here is some clarification:

1. You executed a schema change in your app (created table foo) 

 - correct. Create/drop table foo is what I used for debug evaluations, my assumption is that this code should not fail if all queries meet schema agreement

session.execute("CREATE TABLE foo (user_id uuid, name text, PRIMARY KEY (user_id))");

session.execute("DROP TABLE foo");

session.execute("CREATE TABLE foo (user_id uuid, name text, PRIMARY KEY (user_id))");

session.execute("DROP TABLE foo");

session.execute("CREATE TABLE foo (user_id uuid, name text, PRIMARY KEY (user_id))");

session.execute("DROP TABLE foo");

     2. node3 (10.1.1.115) logged that it was creating the table (that first log entry was from node3 right, or was it from another node?), but when cqlsh'ing to node 3 you could not effectively query it.

- correct (initially table usage failed in application, but I double checked with cqlsh that is not exist)

       3. However, you could create the table on node3 and after that you were able to query it.

- correct. Table can be created/dropped by cqlsh'ing to node3 and also from app if query routed to another node

Currently schema has the same version on all the nodes.

Schema agreement was my initial idea, but returned ResultSet.getExecutionInfo().isSchemaInAgreement() is always true. Also I didn't find in logs this warn "No schema agreement from live replicas after {} s. The schema may not be up to date on some nodes.", that I believe should be in this case.

Cassandra version is the same on all nodes. Will try to reproduce and give you more info.

Thanks,

Igor S

--
You received this message because you are subscribed to the Google Groups "DataStax Java Driver for Apache Cassandra User Mailing List" group.
To unsubscribe from this group and stop receiving emails from it, send an email to java-driver-us...@lists.datastax.com.

[Игорь С]

Reproduced with schema version check:

1. Schema version before create table

vagrant@node3:/var/log/cassandra$ date

Fri Jul  1 14:49:33 UTC 2016

vagrant@node3:/var/log/cassandra$ nodetool describecluster

Cluster Information:

        Name: c_cluster

        Snitch: org.apache.cassandra.locator.DynamicEndpointSnitch

        Partitioner: org.apache.cassandra.dht.Murmur3Partitioner

        Schema versions:

                0b57acd3-7650-3a1c-9bd8-d2f426781997: [10.1.1.113, 10.1.1.115, 10.1.1.114]

2. Run create table from app, wasApplied and schemaInAgreement are true  in result's ExecutionInfo :

3. Cassandara log contains new info about create table issued, however schema version remains the same as before

DEBUG [MigrationStage:1] 2016-07-01 14:49:24,291 MigrationManager.java:493 - Gossiping my schema version 89dc3713-d4c8-3cc7-8f83-ae1d58b7d1a5

DEBUG [GossipStage:1] 2016-07-01 14:49:24,423 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 14:49:24,423 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 14:49:25,400 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 14:49:25,400 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [MigrationStage:1] 2016-07-01 14:49:25,538 MigrationManager.java:493 - Gossiping my schema version 0b57acd3-7650-3a1c-9bd8-d2f426781997

DEBUG [GossipStage:1] 2016-07-01 14:49:26,385 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 14:49:26,486 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 14:49:27,369 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

INFO  [SharedPool-Worker-1] 2016-07-01 14:49:47,491 MigrationManager.java:308 - Create new table: org.apache.cassandra.config.CFMetaData@75089720[cfId=0e5e2330-3f9b-11e6-8953-a120c4d78cc6,ksName=xxx,cfName=foo,cfType=Standard,comparator=org.apache.cassandra.db.marshal.CompositeType(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.UUIDType,minCompactionThreshold=4,maxCompactionThreshold=32,columnMetadata=[ColumnDefinition{name=user_id, type=org.apache.cassandra.db.marshal.UUIDType, kind=PARTITION_KEY, componentIndex=null, indexName=null, indexType=null}, ColumnDefinition{name=name, type=org.apache.cassandra.db.marshal.UTF8Type, kind=REGULAR, componentIndex=0, 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=false]

DEBUG [MigrationStage:1] 2016-07-01 14:49:47,542 MigrationManager.java:493 - Gossiping my schema version 0b57acd3-7650-3a1c-9bd8-d2f426781997

DEBUG [GossipStage:1] 2016-07-01 14:49:48,053 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

DEBUG [GossipStage:1] 2016-07-01 14:49:48,500 MigrationManager.java:96 - Not pulling schema because versions match or shouldPullSchemaFrom returned false

4. Check schema version - the same as before

vagrant@node3:/var/log/cassandra$ date

Fri Jul  1 14:49:53 UTC 2016

vagrant@node3:/var/log/cassandra$ nodetool describecluster

Cluster Information:

        Name: c_cluster

        Snitch: org.apache.cassandra.locator.DynamicEndpointSnitch

        Partitioner: org.apache.cassandra.dht.Murmur3Partitioner

        Schema versions:

                0b57acd3-7650-3a1c-9bd8-d2f426781997: [10.1.1.113, 10.1.1.115, 10.1.1.114]

Thanks,

Igor S

[Andrew Tolbert]

Hi Igor,

That is really interesting.  I had always thought schema version would change when there was a schema change.   That seems like it could be a but in C*.   Since you are on 2.2.4, would you be able to try this on 2.2.6 to see if by chance that there was an issue that was possibly fixed?  It might be good to forward this on to the cassandra user list to see if anyone on there has any ideas.

As an aside, I just had a thought, there was a bug in java driver 3.0.0 (JAVA-1140) where the driver could possibly use a different host to check schema agreement than where the schema change was made.  That could cause it to prematurely think that the schema was in agreement since another nodes view of schema versions could be different since it hasn't gotten the changes over gossip yet.  That might not be related to this particular issue, but it might be worth trying to upgrade to java driver 3.0.2 to see if that helps. 

Thanks,

Andy

[Andrew Tolbert]

That seems like it could be a but in C*

Sorry that was a spelling error, I meant:

That seems like it could be a bug in C* 

[Игорь С]

Hi Andy,

Looks like when initially I got these errors it was due to the bug you mentioned - it happen not always, but from time to time. 

But today something (no idea what exactly) changed and I'm getting what described in this thread.

Will try to update driver and cassadra and check.

Thanks a lot for the help!

Igor S

--