cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Kishan Karunaratne (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CASSANDRA-9310) Table change response returns as keyspace change response
Date Tue, 05 May 2015 21:32:00 GMT

     [ https://issues.apache.org/jira/browse/CASSANDRA-9310?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Kishan Karunaratne updated CASSANDRA-9310:
------------------------------------------
    Description: 
When an index is dropped, its existence is still persisted across the keyspace metadata. This happens because the response to drop the index from the metadata is never received, as a keyspace change response is (incorrectly) received by the driver instead of a table change response.

Test:
{noformat}
self.session.execute("CREATE TABLE %s (k int PRIMARY KEY, a int)" % self.table_name)

ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
table_meta = ks_meta.tables[self.table_name]
self.assertNotIn('a_idx', ks_meta.indexes)
self.assertNotIn('b_idx', ks_meta.indexes)
self.assertNotIn('a_idx', table_meta.indexes)
self.assertNotIn('b_idx', table_meta.indexes)

self.session.execute("CREATE INDEX a_idx ON %s (a)" % self.table_name)
self.session.execute("ALTER TABLE %s ADD b int" % self.table_name)
self.session.execute("CREATE INDEX b_idx ON %s (b)" % self.table_name)

ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
table_meta = ks_meta.tables[self.table_name]
self.assertIsInstance(ks_meta.indexes['a_idx'], IndexMetadata)
self.assertIsInstance(ks_meta.indexes['b_idx'], IndexMetadata)
self.assertIsInstance(table_meta.indexes['a_idx'], IndexMetadata)
self.assertIsInstance(table_meta.indexes['b_idx'], IndexMetadata)

# both indexes updated when index dropped
self.session.execute("DROP INDEX a_idx")
ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
table_meta = ks_meta.tables[self.table_name]
self.assertNotIn('a_idx', ks_meta.indexes)
{noformat}

Output:
{noformat}
AssertionError: 'a_idx' unexpectedly found in {u'b_idx': <cassandra.metadata.IndexMetadata object at 0x7f2dd87d4590>, u'a_idx': <cassandra.metadata.IndexMetadata object at 0x7f2dd87d4a10>}
{noformat}

Debug log:
{noformat}
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test3rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test3rf; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test3rf, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test2rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test2rf; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test2rf, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test3rf, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test1rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test1rf; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test1rf, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test2rf, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test1rf, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test3rf', 'change_type': u'CREATED', 'table': u'test'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test3rf; Table: test, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for test3rf.test, rebuilding metadata
cassandra.cluster: DEBUG: Shutting down Cluster Scheduler
cassandra.cluster: DEBUG: Shutting down control connection
cassandra.io.libevreactor: DEBUG: Closing connection (140309742864976) to 127.0.0.1
cassandra.cluster: DEBUG: Not executing scheduled task due to Scheduler shutdown
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closing connection (140309743075024) to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closing connection (140309742558608) to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closing connection (140309742557904) to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closing connection (140309742557200) to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closing connection (140309742559056) to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closing connection (140309742557840) to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
cassandra.io.libevreactor: DEBUG: All Connections currently closed, event loop ended
cassandra.cluster: DEBUG: Connecting to cluster, contact points: ['127.0.0.1']; protocol version: 1
cassandra.pool: DEBUG: Host 127.0.0.1 is now marked up
cassandra.cluster: DEBUG: [control connection] Opening new connection to 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742559120) to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Starting libev event loop
cassandra.connection: DEBUG: Received options response on new connection (140309742559120) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742559120) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742559120) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742559120) from 127.0.0.1
cassandra.cluster: DEBUG: [control connection] Established new connection <LibevConnection(140309742559120) 127.0.0.1:9042>, registering watchers and refreshing schema and topology
cassandra.cluster: DEBUG: [control connection] Refreshing node list and token map using preloaded results
cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.3
cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.3 dc1> discovered
cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.3 dc1> and notifying listeners
cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.3 dc1>
cassandra.pool: DEBUG: Host 127.0.0.3 is now marked up
cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.2
cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.2 dc1> discovered
cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.2 dc1> and notifying listeners
cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.2 dc1>
cassandra.pool: DEBUG: Host 127.0.0.2 is now marked up
cassandra.cluster: DEBUG: [control connection] Finished fetching ring info
cassandra.cluster: DEBUG: [control connection] Rebuilding token map due to topology changes
cassandra.cluster: DEBUG: [control connection] Attempting to use preloaded results for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] triggers table not found
cassandra.cluster: DEBUG: [control connection] user types table not found
cassandra.cluster: DEBUG: [control connection] Fetched schema, rebuilding metadata
cassandra.metadata: WARNING: Building table metadata with no column meta for system.HintsColumnFamily
cassandra.metadata: WARNING: Building table metadata with no column meta for system.IndexInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.LocationInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.Migrations
cassandra.metadata: WARNING: Building table metadata with no column meta for system.NodeIdInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.Schema
cassandra.metadata: WARNING: Building table metadata with no column meta for system.hints
cassandra.cluster: DEBUG: Control connection created
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.3
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.2
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700367952) to 127.0.0.2
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742595920) to 127.0.0.3
cassandra.connection: DEBUG: Received options response on new connection (140309700367952) from 127.0.0.2
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700367952) 127.0.0.2:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700367952) 127.0.0.2:9042>
cassandra.connection: DEBUG: Received options response on new connection (140309742595920) from 127.0.0.3
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742595920) 127.0.0.3:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742595920) 127.0.0.3:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700367952) from 127.0.0.2
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742595920) from 127.0.0.3
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742595856) to 127.0.0.3
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700368784) to 127.0.0.2
cassandra.connection: DEBUG: Received options response on new connection (140309742595856) from 127.0.0.3
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742595856) 127.0.0.3:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742595856) 127.0.0.3:9042>
cassandra.connection: DEBUG: Received options response on new connection (140309700368784) from 127.0.0.2
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700368784) 127.0.0.2:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700368784) 127.0.0.2:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742595856) from 127.0.0.3
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700368784) from 127.0.0.2
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.3
cassandra.cluster: DEBUG: Added pool for host 127.0.0.3 to session
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700369232) to 127.0.0.1
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.2
cassandra.cluster: DEBUG: Added pool for host 127.0.0.2 to session
cassandra.connection: DEBUG: Received options response on new connection (140309700369232) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700369232) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700369232) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700369232) from 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700367888) to 127.0.0.1
cassandra.connection: DEBUG: Received options response on new connection (140309700367888) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700367888) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700367888) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700367888) from 127.0.0.1
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.1
cassandra.cluster: DEBUG: Added pool for host 127.0.0.1 to session
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'CREATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Ignoring schedule_unique for already-scheduled task: (<bound method ControlConnection.refresh_schema of <cassandra.cluster.ControlConnection object at 0x7f9c6864fc90>>, (u'index_map_tests', u'test_index_updates', None))
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
{noformat}

  was:
When an index is dropped, its existence is still persisted across the keyspace metadata. This happens because the response to drop the index from the metadata is never received, as a keyspace change response is (incorrectly) received by the driver instead of a table change response.

Test:
{noformat}
self.session.execute("CREATE TABLE %s (k int PRIMARY KEY, a int)" % self.table_name)

ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
table_meta = ks_meta.tables[self.table_name]
self.assertNotIn('a_idx', ks_meta.indexes)
self.assertNotIn('b_idx', ks_meta.indexes)
self.assertNotIn('a_idx', table_meta.indexes)
self.assertNotIn('b_idx', table_meta.indexes)

self.session.execute("CREATE INDEX a_idx ON %s (a)" % self.table_name)
self.session.execute("ALTER TABLE %s ADD b int" % self.table_name)
self.session.execute("CREATE INDEX b_idx ON %s (b)" % self.table_name)

ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
table_meta = ks_meta.tables[self.table_name]
self.assertIsInstance(ks_meta.indexes['a_idx'], IndexMetadata)
self.assertIsInstance(ks_meta.indexes['b_idx'], IndexMetadata)
self.assertIsInstance(table_meta.indexes['a_idx'], IndexMetadata)
self.assertIsInstance(table_meta.indexes['b_idx'], IndexMetadata)

# both indexes updated when index dropped
self.session.execute("DROP INDEX a_idx")
ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
table_meta = ks_meta.tables[self.table_name]
self.assertNotIn('a_idx', ks_meta.indexes)
{noformat}

Output:
{noformat}
AssertionError: 'a_idx' unexpectedly found in {u'b_idx': <cassandra.metadata.IndexMetadata object at 0x7f2dd87d4590>, u'a_idx': <cassandra.metadata.IndexMetadata object at 0x7f2dd87d4a10>}
{noformat}

Debug log:
{noformat}
tests.integration: INFO: Using Cassandra version: 1.2.19
tests.integration: DEBUG: Creating new ccm test_cluster cluster with {'version': '1.2.19'}
tests.integration: DEBUG: Starting ccm test_cluster cluster
cassandra.cluster: DEBUG: Connecting to cluster, contact points: ['127.0.0.1']; protocol version: 1
cassandra.pool: DEBUG: Host 127.0.0.1 is now marked up
cassandra.cluster: DEBUG: [control connection] Opening new connection to 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742864976) to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Starting libev event loop
cassandra.connection: DEBUG: Received options response on new connection (140309742864976) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742864976) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742864976) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742864976) from 127.0.0.1
cassandra.cluster: DEBUG: [control connection] Established new connection <LibevConnection(140309742864976) 127.0.0.1:9042>, registering watchers and refreshing schema and topology
cassandra.cluster: DEBUG: [control connection] Refreshing node list and token map using preloaded results
cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.3
cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.3 dc1> discovered
cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.3 dc1> and notifying listeners
cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.3 dc1>
cassandra.pool: DEBUG: Host 127.0.0.3 is now marked up
cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.2
cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.2 dc1> discovered
cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.2 dc1> and notifying listeners
cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.2 dc1>
cassandra.pool: DEBUG: Host 127.0.0.2 is now marked up
cassandra.cluster: DEBUG: [control connection] Finished fetching ring info
cassandra.cluster: DEBUG: [control connection] Rebuilding token map due to topology changes
cassandra.cluster: DEBUG: [control connection] Attempting to use preloaded results for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] triggers table not found
cassandra.cluster: DEBUG: [control connection] user types table not found
cassandra.cluster: DEBUG: [control connection] Fetched schema, rebuilding metadata
cassandra.metadata: WARNING: Building table metadata with no column meta for system.HintsColumnFamily
cassandra.metadata: WARNING: Building table metadata with no column meta for system.IndexInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.LocationInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.Migrations
cassandra.metadata: WARNING: Building table metadata with no column meta for system.NodeIdInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.Schema
cassandra.metadata: WARNING: Building table metadata with no column meta for system.hints
cassandra.cluster: DEBUG: Control connection created
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.3
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.2
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742557904) to 127.0.0.2
cassandra.connection: DEBUG: Sending initial options message for new connection (140309743075024) to 127.0.0.3
cassandra.connection: DEBUG: Received options response on new connection (140309743075024) from 127.0.0.3
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309743075024) 127.0.0.3:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309743075024) 127.0.0.3:9042>
cassandra.connection: DEBUG: Received options response on new connection (140309742557904) from 127.0.0.2
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742557904) 127.0.0.2:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742557904) 127.0.0.2:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309743075024) from 127.0.0.3
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742557904) from 127.0.0.2
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742557200) to 127.0.0.2
cassandra.connection: DEBUG: Received options response on new connection (140309742557200) from 127.0.0.2
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742557200) 127.0.0.2:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742557200) 127.0.0.2:9042>
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742558608) to 127.0.0.3
cassandra.connection: DEBUG: Received options response on new connection (140309742558608) from 127.0.0.3
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742558608) 127.0.0.3:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742558608) 127.0.0.3:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742558608) from 127.0.0.3
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.3
cassandra.cluster: DEBUG: Added pool for host 127.0.0.3 to session
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742559056) to 127.0.0.1
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742557200) from 127.0.0.2
cassandra.connection: DEBUG: Received options response on new connection (140309742559056) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742559056) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742559056) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742559056) from 127.0.0.1
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.2
cassandra.cluster: DEBUG: Added pool for host 127.0.0.2 to session
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742557840) to 127.0.0.1
cassandra.connection: DEBUG: Received options response on new connection (140309742557840) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742557840) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742557840) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742557840) from 127.0.0.1
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.1
cassandra.cluster: DEBUG: Added pool for host 127.0.0.1 to session
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test3rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test3rf; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test3rf, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test2rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test2rf; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test2rf, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test3rf, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test1rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test1rf; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test1rf, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test2rf, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test1rf, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test3rf', 'change_type': u'CREATED', 'table': u'test'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test3rf; Table: test, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for test3rf.test, rebuilding metadata
cassandra.cluster: DEBUG: Shutting down Cluster Scheduler
cassandra.cluster: DEBUG: Shutting down control connection
cassandra.io.libevreactor: DEBUG: Closing connection (140309742864976) to 127.0.0.1
cassandra.cluster: DEBUG: Not executing scheduled task due to Scheduler shutdown
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closing connection (140309743075024) to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closing connection (140309742558608) to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.3
cassandra.io.libevreactor: DEBUG: Closing connection (140309742557904) to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closing connection (140309742557200) to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.2
cassandra.io.libevreactor: DEBUG: Closing connection (140309742559056) to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closing connection (140309742557840) to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
cassandra.io.libevreactor: DEBUG: All Connections currently closed, event loop ended
cassandra.cluster: DEBUG: Connecting to cluster, contact points: ['127.0.0.1']; protocol version: 1
cassandra.pool: DEBUG: Host 127.0.0.1 is now marked up
cassandra.cluster: DEBUG: [control connection] Opening new connection to 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742559120) to 127.0.0.1
cassandra.io.libevreactor: DEBUG: Starting libev event loop
cassandra.connection: DEBUG: Received options response on new connection (140309742559120) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742559120) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742559120) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742559120) from 127.0.0.1
cassandra.cluster: DEBUG: [control connection] Established new connection <LibevConnection(140309742559120) 127.0.0.1:9042>, registering watchers and refreshing schema and topology
cassandra.cluster: DEBUG: [control connection] Refreshing node list and token map using preloaded results
cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.3
cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.3 dc1> discovered
cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.3 dc1> and notifying listeners
cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.3 dc1>
cassandra.pool: DEBUG: Host 127.0.0.3 is now marked up
cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.2
cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.2 dc1> discovered
cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.2 dc1> and notifying listeners
cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.2 dc1>
cassandra.pool: DEBUG: Host 127.0.0.2 is now marked up
cassandra.cluster: DEBUG: [control connection] Finished fetching ring info
cassandra.cluster: DEBUG: [control connection] Rebuilding token map due to topology changes
cassandra.cluster: DEBUG: [control connection] Attempting to use preloaded results for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] triggers table not found
cassandra.cluster: DEBUG: [control connection] user types table not found
cassandra.cluster: DEBUG: [control connection] Fetched schema, rebuilding metadata
cassandra.metadata: WARNING: Building table metadata with no column meta for system.HintsColumnFamily
cassandra.metadata: WARNING: Building table metadata with no column meta for system.IndexInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.LocationInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.Migrations
cassandra.metadata: WARNING: Building table metadata with no column meta for system.NodeIdInfo
cassandra.metadata: WARNING: Building table metadata with no column meta for system.Schema
cassandra.metadata: WARNING: Building table metadata with no column meta for system.hints
cassandra.cluster: DEBUG: Control connection created
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.3
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.2
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700367952) to 127.0.0.2
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742595920) to 127.0.0.3
cassandra.connection: DEBUG: Received options response on new connection (140309700367952) from 127.0.0.2
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700367952) 127.0.0.2:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700367952) 127.0.0.2:9042>
cassandra.connection: DEBUG: Received options response on new connection (140309742595920) from 127.0.0.3
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742595920) 127.0.0.3:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742595920) 127.0.0.3:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700367952) from 127.0.0.2
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742595920) from 127.0.0.3
cassandra.connection: DEBUG: Sending initial options message for new connection (140309742595856) to 127.0.0.3
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700368784) to 127.0.0.2
cassandra.connection: DEBUG: Received options response on new connection (140309742595856) from 127.0.0.3
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742595856) 127.0.0.3:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742595856) 127.0.0.3:9042>
cassandra.connection: DEBUG: Received options response on new connection (140309700368784) from 127.0.0.2
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700368784) 127.0.0.2:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700368784) 127.0.0.2:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742595856) from 127.0.0.3
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700368784) from 127.0.0.2
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.3
cassandra.cluster: DEBUG: Added pool for host 127.0.0.3 to session
cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700369232) to 127.0.0.1
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.2
cassandra.cluster: DEBUG: Added pool for host 127.0.0.2 to session
cassandra.connection: DEBUG: Received options response on new connection (140309700369232) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700369232) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700369232) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700369232) from 127.0.0.1
cassandra.connection: DEBUG: Sending initial options message for new connection (140309700367888) to 127.0.0.1
cassandra.connection: DEBUG: Received options response on new connection (140309700367888) from 127.0.0.1
cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700367888) 127.0.0.1:9042>
cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700367888) 127.0.0.1:9042>
cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700367888) from 127.0.0.1
cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.1
cassandra.cluster: DEBUG: Added pool for host 127.0.0.1 to session
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'CREATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Ignoring schedule_unique for already-scheduled task: (<bound method ControlConnection.refresh_schema of <cassandra.cluster.ControlConnection object at 0x7f9c6864fc90>>, (u'index_map_tests', u'test_index_updates', None))
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: , Type: None
cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
cassandra.cluster: DEBUG: [control connection] Schemas match
cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
{noformat}


> Table change response returns as keyspace change response
> ---------------------------------------------------------
>
>                 Key: CASSANDRA-9310
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-9310
>             Project: Cassandra
>          Issue Type: Bug
>         Environment: C* 1.2.19 and 2.0.14 | python-driver master (upcoming v. 2.6)
>            Reporter: Kishan Karunaratne
>
> When an index is dropped, its existence is still persisted across the keyspace metadata. This happens because the response to drop the index from the metadata is never received, as a keyspace change response is (incorrectly) received by the driver instead of a table change response.
> Test:
> {noformat}
> self.session.execute("CREATE TABLE %s (k int PRIMARY KEY, a int)" % self.table_name)
> ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
> table_meta = ks_meta.tables[self.table_name]
> self.assertNotIn('a_idx', ks_meta.indexes)
> self.assertNotIn('b_idx', ks_meta.indexes)
> self.assertNotIn('a_idx', table_meta.indexes)
> self.assertNotIn('b_idx', table_meta.indexes)
> self.session.execute("CREATE INDEX a_idx ON %s (a)" % self.table_name)
> self.session.execute("ALTER TABLE %s ADD b int" % self.table_name)
> self.session.execute("CREATE INDEX b_idx ON %s (b)" % self.table_name)
> ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
> table_meta = ks_meta.tables[self.table_name]
> self.assertIsInstance(ks_meta.indexes['a_idx'], IndexMetadata)
> self.assertIsInstance(ks_meta.indexes['b_idx'], IndexMetadata)
> self.assertIsInstance(table_meta.indexes['a_idx'], IndexMetadata)
> self.assertIsInstance(table_meta.indexes['b_idx'], IndexMetadata)
> # both indexes updated when index dropped
> self.session.execute("DROP INDEX a_idx")
> ks_meta = self.cluster.metadata.keyspaces[self.keyspace_name]
> table_meta = ks_meta.tables[self.table_name]
> self.assertNotIn('a_idx', ks_meta.indexes)
> {noformat}
> Output:
> {noformat}
> AssertionError: 'a_idx' unexpectedly found in {u'b_idx': <cassandra.metadata.IndexMetadata object at 0x7f2dd87d4590>, u'a_idx': <cassandra.metadata.IndexMetadata object at 0x7f2dd87d4a10>}
> {noformat}
> Debug log:
> {noformat}
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test3rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test3rf; Table: , Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test3rf, rebuilding metadata
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test2rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test2rf; Table: , Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test2rf, rebuilding metadata
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test3rf, rebuilding metadata
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test1rf', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test1rf; Table: , Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test1rf, rebuilding metadata
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test2rf, rebuilding metadata
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for test1rf, rebuilding metadata
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'test3rf', 'change_type': u'CREATED', 'table': u'test'}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: test3rf; Table: test, Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched table info for test3rf.test, rebuilding metadata
> cassandra.cluster: DEBUG: Shutting down Cluster Scheduler
> cassandra.cluster: DEBUG: Shutting down control connection
> cassandra.io.libevreactor: DEBUG: Closing connection (140309742864976) to 127.0.0.1
> cassandra.cluster: DEBUG: Not executing scheduled task due to Scheduler shutdown
> cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
> cassandra.io.libevreactor: DEBUG: Closing connection (140309743075024) to 127.0.0.3
> cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.3
> cassandra.io.libevreactor: DEBUG: Closing connection (140309742558608) to 127.0.0.3
> cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.3
> cassandra.io.libevreactor: DEBUG: Closing connection (140309742557904) to 127.0.0.2
> cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.2
> cassandra.io.libevreactor: DEBUG: Closing connection (140309742557200) to 127.0.0.2
> cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.2
> cassandra.io.libevreactor: DEBUG: Closing connection (140309742559056) to 127.0.0.1
> cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
> cassandra.io.libevreactor: DEBUG: Closing connection (140309742557840) to 127.0.0.1
> cassandra.io.libevreactor: DEBUG: Closed socket to 127.0.0.1
> cassandra.io.libevreactor: DEBUG: All Connections currently closed, event loop ended
> cassandra.cluster: DEBUG: Connecting to cluster, contact points: ['127.0.0.1']; protocol version: 1
> cassandra.pool: DEBUG: Host 127.0.0.1 is now marked up
> cassandra.cluster: DEBUG: [control connection] Opening new connection to 127.0.0.1
> cassandra.connection: DEBUG: Sending initial options message for new connection (140309742559120) to 127.0.0.1
> cassandra.io.libevreactor: DEBUG: Starting libev event loop
> cassandra.connection: DEBUG: Received options response on new connection (140309742559120) from 127.0.0.1
> cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742559120) 127.0.0.1:9042>
> cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742559120) 127.0.0.1:9042>
> cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742559120) from 127.0.0.1
> cassandra.cluster: DEBUG: [control connection] Established new connection <LibevConnection(140309742559120) 127.0.0.1:9042>, registering watchers and refreshing schema and topology
> cassandra.cluster: DEBUG: [control connection] Refreshing node list and token map using preloaded results
> cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.3
> cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.3 dc1> discovered
> cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.3 dc1> and notifying listeners
> cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.3 dc1>
> cassandra.pool: DEBUG: Host 127.0.0.3 is now marked up
> cassandra.cluster: DEBUG: [control connection] Found new host to connect to: 127.0.0.2
> cassandra.cluster: INFO: New Cassandra host <Host: 127.0.0.2 dc1> discovered
> cassandra.cluster: DEBUG: Handling new host <Host: 127.0.0.2 dc1> and notifying listeners
> cassandra.cluster: DEBUG: Done preparing queries for new host <Host: 127.0.0.2 dc1>
> cassandra.pool: DEBUG: Host 127.0.0.2 is now marked up
> cassandra.cluster: DEBUG: [control connection] Finished fetching ring info
> cassandra.cluster: DEBUG: [control connection] Rebuilding token map due to topology changes
> cassandra.cluster: DEBUG: [control connection] Attempting to use preloaded results for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] triggers table not found
> cassandra.cluster: DEBUG: [control connection] user types table not found
> cassandra.cluster: DEBUG: [control connection] Fetched schema, rebuilding metadata
> cassandra.metadata: WARNING: Building table metadata with no column meta for system.HintsColumnFamily
> cassandra.metadata: WARNING: Building table metadata with no column meta for system.IndexInfo
> cassandra.metadata: WARNING: Building table metadata with no column meta for system.LocationInfo
> cassandra.metadata: WARNING: Building table metadata with no column meta for system.Migrations
> cassandra.metadata: WARNING: Building table metadata with no column meta for system.NodeIdInfo
> cassandra.metadata: WARNING: Building table metadata with no column meta for system.Schema
> cassandra.metadata: WARNING: Building table metadata with no column meta for system.hints
> cassandra.cluster: DEBUG: Control connection created
> cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.3
> cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.2
> cassandra.connection: DEBUG: Sending initial options message for new connection (140309700367952) to 127.0.0.2
> cassandra.connection: DEBUG: Sending initial options message for new connection (140309742595920) to 127.0.0.3
> cassandra.connection: DEBUG: Received options response on new connection (140309700367952) from 127.0.0.2
> cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700367952) 127.0.0.2:9042>
> cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700367952) 127.0.0.2:9042>
> cassandra.connection: DEBUG: Received options response on new connection (140309742595920) from 127.0.0.3
> cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742595920) 127.0.0.3:9042>
> cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742595920) 127.0.0.3:9042>
> cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700367952) from 127.0.0.2
> cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742595920) from 127.0.0.3
> cassandra.connection: DEBUG: Sending initial options message for new connection (140309742595856) to 127.0.0.3
> cassandra.connection: DEBUG: Sending initial options message for new connection (140309700368784) to 127.0.0.2
> cassandra.connection: DEBUG: Received options response on new connection (140309742595856) from 127.0.0.3
> cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309742595856) 127.0.0.3:9042>
> cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309742595856) 127.0.0.3:9042>
> cassandra.connection: DEBUG: Received options response on new connection (140309700368784) from 127.0.0.2
> cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700368784) 127.0.0.2:9042>
> cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700368784) 127.0.0.2:9042>
> cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309742595856) from 127.0.0.3
> cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700368784) from 127.0.0.2
> cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.3
> cassandra.cluster: DEBUG: Added pool for host 127.0.0.3 to session
> cassandra.pool: DEBUG: Initializing new connection pool for host 127.0.0.1
> cassandra.connection: DEBUG: Sending initial options message for new connection (140309700369232) to 127.0.0.1
> cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.2
> cassandra.cluster: DEBUG: Added pool for host 127.0.0.2 to session
> cassandra.connection: DEBUG: Received options response on new connection (140309700369232) from 127.0.0.1
> cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700369232) 127.0.0.1:9042>
> cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700369232) 127.0.0.1:9042>
> cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700369232) from 127.0.0.1
> cassandra.connection: DEBUG: Sending initial options message for new connection (140309700367888) to 127.0.0.1
> cassandra.connection: DEBUG: Received options response on new connection (140309700367888) from 127.0.0.1
> cassandra.connection: DEBUG: Sending StartupMessage on <LibevConnection(140309700367888) 127.0.0.1:9042>
> cassandra.connection: DEBUG: Sent StartupMessage on <LibevConnection(140309700367888) 127.0.0.1:9042>
> cassandra.connection: DEBUG: Got ReadyMessage on new connection (140309700367888) from 127.0.0.1
> cassandra.pool: DEBUG: Finished initializing new connection pool for host 127.0.0.1
> cassandra.cluster: DEBUG: Added pool for host 127.0.0.1 to session
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'CREATED', 'table': u''}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: , Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'CREATED', 'table': u'test_index_updates'}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
> cassandra.cluster: DEBUG: Ignoring schedule_unique for already-scheduled task: (<bound method ControlConnection.refresh_schema of <cassandra.cluster.ControlConnection object at 0x7f9c6864fc90>>, (u'index_map_tests', u'test_index_updates', None))
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: test_index_updates, Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
> cassandra.cluster: DEBUG: [control connection] Fetched table info for index_map_tests.test_index_updates, rebuilding metadata
> cassandra.connection: DEBUG: Message pushed from server: <EventMessage(stream_id=-1, event_type=u'SCHEMA_CHANGE', event_args={'keyspace': u'index_map_tests', 'change_type': u'UPDATED', 'table': u'test_index_updates'}, trace_id=None)>
> cassandra.cluster: DEBUG: Refreshing schema in response to schema change. Keyspace: index_map_tests; Table: , Type: None
> cassandra.cluster: DEBUG: [control connection] Waiting for schema agreement
> cassandra.cluster: DEBUG: [control connection] Schemas mismatched, trying again
> cassandra.cluster: DEBUG: [control connection] Schemas match
> cassandra.cluster: DEBUG: [control connection] Fetched keyspace info for index_map_tests, rebuilding metadata
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message