| 2014-09-16 08:35:15 |
Illia Khudoshyn |
description |
While sending multiple creation requests (30+) some of tables do not change their status to ACTIVE:
On server side:
2014-06-25 13:23:16.307 9827 DEBUG magnetodb.common.cassandra.cluster_handler [-] Start waiting for table status changing... wait_for_table_status /opt/s
tack/magnetodb/magnetodb/common/cassandra/cluster_handler.py:61
2014-06-25 13:23:16.313 9827 ERROR cassandra.connection [-] Error decoding response from Cassandra. opcode: 0000; message contents: '\x82\x00U\x00\x00\x0
0\x00E\x00\x00\x11\x00\x000Operation timed out - received only 1 responses.\x00\x08\x00\x00\x00\x01\x00\x00\x00\x02\x00\x03CAS'
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 327, in process_msg
response = decode_response(stream_id, flags, opcode, body, self.decompressor)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 121, in decode_response
msg = msg_class.recv_body(body)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 145, in recv_body
extra_info = subcls.recv_error_info(f)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 242, in recv_error_info
'write_type': WriteType.name_to_value[read_string(f)],
KeyError: u'CAS'
2014-06-25 13:23:16.314 9827 DEBUG cassandra.connection [-] Defuncting connection (39912208) to 127.0.0.3: defunct /usr/local/lib/python2.7/dist-packages
/cassandra/connection.py:200
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 327, in process_msg
response = decode_response(stream_id, flags, opcode, body, self.decompressor)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 121, in decode_response
msg = msg_class.recv_body(body)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 145, in recv_body
extra_info = subcls.recv_error_info(f)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 242, in recv_error_info
'write_type': WriteType.name_to_value[read_string(f)],
KeyError: u'CAS'
2014-06-25 13:23:16.314 9827 DEBUG magnetodb.common.cassandra.io.eventletreactor [-] Closing connection (39912208) to 127.0.0.3 close /opt/stack/magnetodb/magnetodb/common/cassandra/io/eventletreactor.py:101
2014-06-25 13:23:16.314 9827 DEBUG magnetodb.common.cassandra.io.eventletreactor [-] Closed socket to 127.0.0.3 close /opt/stack/magnetodb/magnetodb/common/cassandra/io/eventletreactor.py:111
2014-06-25 13:23:16.317 9827 ERROR magnetodb.common.cassandra.cluster_handler [-] Error executing query <SimpleStatement query="UPDATE magnetodb.table_info SET "internal_name"='user_testtempest1620759055' WHERE tenant='728aa7ededef48c98661696d5efd842d' AND name='testtempest1620759055' IF exists=1", consistency=QUORUM>:CAS
Traceback (most recent call last):
File "/opt/stack/magnetodb/magnetodb/common/cassandra/cluster_handler.py", line 46, in execute_query
return self.__session.execute(query)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1103, in execute
result = future.result(timeout)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2473, in result
raise self._final_exception
KeyError: u'CAS'
2014-06-25 13:23:16.318 9827 ERROR openstack.common.notification.magnetodb.table.create.error [-] {"priority": "ERROR", "event_type": "magnetodb.table.create.error", "timestamp": "2014-06-25 13:23:16.318462", "publisher_id": "magnetodb.ubuntu", "payload": {}, "message_id": "a386540a-319b-46b2-b267-a4e8d90a510a"}
2014-06-25 13:23:16.332 9827 INFO openstack.common.notification.magnetodb.table.create.end [-] {"priority": "INFO", "event_type": "magnetodb.table.create.end", "timestamp": "2014-06-25 13:23:16.332446", "publisher_id": "magnetodb.ubuntu", "payload": {"_data": {"attribute_type_map": {"forum": {"_data": {"element_type": "s", "collection_type": null}, "_hash": 8985353558203769482}, "subject": {"_data": {"element_type": "s", "collection_type": null}, "_hash": 8985353558203769482}}, "key_attributes": ["forum", "subject"], "index_def_map": {}}, "_hash": null}, "message_id": "a4091b79-a2e8-4539-a723-6f77c61ba71d"}
2014-06-25 13:23:16.351 9827 DEBUG cassandra.cluster [-] [control connection] Schemas match _get_schema_mismatches /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py:1909
2014-06-25 13:23:16.353 9827 DEBUG cassandra.cluster [-] [control connection] Waiting for schema agreement wait_for_schema_agreement /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py:1850
2014-06-25 13:23:16.353 9827 ERROR cassandra.cluster [-] Exception refreshing schema in response to schema change:
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2032, in refresh_schema_and_set_result
control_conn._refresh_schema(response_future._connection, keyspace, table)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1654, in _refresh_schema
agreed = self.wait_for_schema_agreement(connection, preloaded_results=preloaded_results)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1862, in wait_for_schema_agreement
peers_query, local_query, timeout=timeout)
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 253, in wait_for_responses
raise ConnectionShutdown("Connection %s is already closed" % (self, ))
ConnectionShutdown: Connection <EventletConnection(39912208) 127.0.0.3:9042 (defunct)> is already closed
2014-06-25 13:23:16.438 9827 DEBUG cassandra.cluster [-] Error querying host 127.0.0.3 _query /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py
:2137
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2131, in _query
request_id = connection.send_msg(message, cb=cb)
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 231, in send_msg
raise ConnectionShutdown("Connection to %s is defunct" % self.host)
ConnectionShutdown: Connection to 127.0.0.3 is defunct
2014-06-25 13:23:16.439 9827 DEBUG cassandra.pool [-] Defunct or closed connection (39912208) returned to pool, potentially marking host 127.0.0.3 as dow
n return_connection /usr/local/lib/python2.7/dist-packages/cassandra/pool.py:479
2014-06-25 13:23:16.439 9827 DEBUG magnetodb.common.cassandra.io.eventletreactor [-] Closing connection (39914640) to 127.0.0.3 close /opt/stack/magnetod
b/magnetodb/common/cassandra/io/eventletreactor.py:101
2014-06-25 13:23:16.439 9827 DEBUG cassandra.cluster [-] [control connection] Schemas match _get_schema_mismatches /usr/local/lib/python2.7/dist-packages
/cassandra/cluster.py:1909
2014-06-25 13:23:16.439 9827 DEBUG magnetodb.common.cassandra.cluster_handler [-] Table status is correct (expected_exists: True, table_meta: <cassandra.
metadata.TableMetadata object at 0x2f95350>). wait_for_table_status /opt/stack/magnetodb/magnetodb/common/cassandra/cluster_handler.py:90
2014-06-25 13:23:16.440 9827 DEBUG magnetodb.storage.driver.cassandra.cassandra_impl [-] Waiting for schema agreement... Done create_table /opt/stack/mag
netodb/magnetodb/storage/driver/cassandra/cassandra_impl.py:263
2014-06-25 13:23:16.440 9827 DEBUG magnetodb.common.cassandra.cluster_handler [-] Executing query <SimpleStatement query="UPDATE magnetodb.table_info SET "internal_name"='user_testtempest506424481' WHERE tenant='728aa7ededef48c98661696d5efd842d' AND name='testtempest506424481' IF exists=1", consistency=QUORUM> execute_query /opt/stack/magnetodb/magnetodb/common/cassandra/cluster_handler.py:42
2014-06-25 13:23:16.440 9827 DEBUG cassandra.cluster [-] [control connection] Waiting for schema agreement wait_for_schema_agreement /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py:1850
2014-06-25 13:23:16.440 9827 ERROR cassandra.cluster [-] Exception refreshing schema in response to schema change:
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2032, in refresh_schema_and_set_result
control_conn._refresh_schema(response_future._connection, keyspace, table)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1654, in _refresh_schema
agreed = self.wait_for_schema_agreement(connection, preloaded_results=preloaded_results)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1862, in wait_for_schema_agreement
peers_query, local_query, timeout=timeout)
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 253, in wait_for_responses
raise ConnectionShutdown("Connection %s is already closed" % (self, ))
ConnectionShutdown: Connection <EventletConnection(39914640) 127.0.0.3:9042 (closed)> is already closed |
While sending multiple creation requests (30+) some of tables do not change their status to ACTIVE:
[IK] In fact, this behaviour may occur even during much less load, like 2-3 concurrent table create/delete operations may cause it.
On server side:
2014-06-25 13:23:16.307 9827 DEBUG magnetodb.common.cassandra.cluster_handler [-] Start waiting for table status changing... wait_for_table_status /opt/s
tack/magnetodb/magnetodb/common/cassandra/cluster_handler.py:61
2014-06-25 13:23:16.313 9827 ERROR cassandra.connection [-] Error decoding response from Cassandra. opcode: 0000; message contents: '\x82\x00U\x00\x00\x0
0\x00E\x00\x00\x11\x00\x000Operation timed out - received only 1 responses.\x00\x08\x00\x00\x00\x01\x00\x00\x00\x02\x00\x03CAS'
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 327, in process_msg
response = decode_response(stream_id, flags, opcode, body, self.decompressor)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 121, in decode_response
msg = msg_class.recv_body(body)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 145, in recv_body
extra_info = subcls.recv_error_info(f)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 242, in recv_error_info
'write_type': WriteType.name_to_value[read_string(f)],
KeyError: u'CAS'
2014-06-25 13:23:16.314 9827 DEBUG cassandra.connection [-] Defuncting connection (39912208) to 127.0.0.3: defunct /usr/local/lib/python2.7/dist-packages
/cassandra/connection.py:200
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 327, in process_msg
response = decode_response(stream_id, flags, opcode, body, self.decompressor)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 121, in decode_response
msg = msg_class.recv_body(body)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 145, in recv_body
extra_info = subcls.recv_error_info(f)
File "/usr/local/lib/python2.7/dist-packages/cassandra/protocol.py", line 242, in recv_error_info
'write_type': WriteType.name_to_value[read_string(f)],
KeyError: u'CAS'
2014-06-25 13:23:16.314 9827 DEBUG magnetodb.common.cassandra.io.eventletreactor [-] Closing connection (39912208) to 127.0.0.3 close /opt/stack/magnetodb/magnetodb/common/cassandra/io/eventletreactor.py:101
2014-06-25 13:23:16.314 9827 DEBUG magnetodb.common.cassandra.io.eventletreactor [-] Closed socket to 127.0.0.3 close /opt/stack/magnetodb/magnetodb/common/cassandra/io/eventletreactor.py:111
2014-06-25 13:23:16.317 9827 ERROR magnetodb.common.cassandra.cluster_handler [-] Error executing query <SimpleStatement query="UPDATE magnetodb.table_info SET "internal_name"='user_testtempest1620759055' WHERE tenant='728aa7ededef48c98661696d5efd842d' AND name='testtempest1620759055' IF exists=1", consistency=QUORUM>:CAS
Traceback (most recent call last):
File "/opt/stack/magnetodb/magnetodb/common/cassandra/cluster_handler.py", line 46, in execute_query
return self.__session.execute(query)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1103, in execute
result = future.result(timeout)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2473, in result
raise self._final_exception
KeyError: u'CAS'
2014-06-25 13:23:16.318 9827 ERROR openstack.common.notification.magnetodb.table.create.error [-] {"priority": "ERROR", "event_type": "magnetodb.table.create.error", "timestamp": "2014-06-25 13:23:16.318462", "publisher_id": "magnetodb.ubuntu", "payload": {}, "message_id": "a386540a-319b-46b2-b267-a4e8d90a510a"}
2014-06-25 13:23:16.332 9827 INFO openstack.common.notification.magnetodb.table.create.end [-] {"priority": "INFO", "event_type": "magnetodb.table.create.end", "timestamp": "2014-06-25 13:23:16.332446", "publisher_id": "magnetodb.ubuntu", "payload": {"_data": {"attribute_type_map": {"forum": {"_data": {"element_type": "s", "collection_type": null}, "_hash": 8985353558203769482}, "subject": {"_data": {"element_type": "s", "collection_type": null}, "_hash": 8985353558203769482}}, "key_attributes": ["forum", "subject"], "index_def_map": {}}, "_hash": null}, "message_id": "a4091b79-a2e8-4539-a723-6f77c61ba71d"}
2014-06-25 13:23:16.351 9827 DEBUG cassandra.cluster [-] [control connection] Schemas match _get_schema_mismatches /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py:1909
2014-06-25 13:23:16.353 9827 DEBUG cassandra.cluster [-] [control connection] Waiting for schema agreement wait_for_schema_agreement /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py:1850
2014-06-25 13:23:16.353 9827 ERROR cassandra.cluster [-] Exception refreshing schema in response to schema change:
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2032, in refresh_schema_and_set_result
control_conn._refresh_schema(response_future._connection, keyspace, table)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1654, in _refresh_schema
agreed = self.wait_for_schema_agreement(connection, preloaded_results=preloaded_results)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1862, in wait_for_schema_agreement
peers_query, local_query, timeout=timeout)
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 253, in wait_for_responses
raise ConnectionShutdown("Connection %s is already closed" % (self, ))
ConnectionShutdown: Connection <EventletConnection(39912208) 127.0.0.3:9042 (defunct)> is already closed
2014-06-25 13:23:16.438 9827 DEBUG cassandra.cluster [-] Error querying host 127.0.0.3 _query /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py
:2137
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2131, in _query
request_id = connection.send_msg(message, cb=cb)
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 231, in send_msg
raise ConnectionShutdown("Connection to %s is defunct" % self.host)
ConnectionShutdown: Connection to 127.0.0.3 is defunct
2014-06-25 13:23:16.439 9827 DEBUG cassandra.pool [-] Defunct or closed connection (39912208) returned to pool, potentially marking host 127.0.0.3 as dow
n return_connection /usr/local/lib/python2.7/dist-packages/cassandra/pool.py:479
2014-06-25 13:23:16.439 9827 DEBUG magnetodb.common.cassandra.io.eventletreactor [-] Closing connection (39914640) to 127.0.0.3 close /opt/stack/magnetod
b/magnetodb/common/cassandra/io/eventletreactor.py:101
2014-06-25 13:23:16.439 9827 DEBUG cassandra.cluster [-] [control connection] Schemas match _get_schema_mismatches /usr/local/lib/python2.7/dist-packages
/cassandra/cluster.py:1909
2014-06-25 13:23:16.439 9827 DEBUG magnetodb.common.cassandra.cluster_handler [-] Table status is correct (expected_exists: True, table_meta: <cassandra.
metadata.TableMetadata object at 0x2f95350>). wait_for_table_status /opt/stack/magnetodb/magnetodb/common/cassandra/cluster_handler.py:90
2014-06-25 13:23:16.440 9827 DEBUG magnetodb.storage.driver.cassandra.cassandra_impl [-] Waiting for schema agreement... Done create_table /opt/stack/mag
netodb/magnetodb/storage/driver/cassandra/cassandra_impl.py:263
2014-06-25 13:23:16.440 9827 DEBUG magnetodb.common.cassandra.cluster_handler [-] Executing query <SimpleStatement query="UPDATE magnetodb.table_info SET "internal_name"='user_testtempest506424481' WHERE tenant='728aa7ededef48c98661696d5efd842d' AND name='testtempest506424481' IF exists=1", consistency=QUORUM> execute_query /opt/stack/magnetodb/magnetodb/common/cassandra/cluster_handler.py:42
2014-06-25 13:23:16.440 9827 DEBUG cassandra.cluster [-] [control connection] Waiting for schema agreement wait_for_schema_agreement /usr/local/lib/python2.7/dist-packages/cassandra/cluster.py:1850
2014-06-25 13:23:16.440 9827 ERROR cassandra.cluster [-] Exception refreshing schema in response to schema change:
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 2032, in refresh_schema_and_set_result
control_conn._refresh_schema(response_future._connection, keyspace, table)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1654, in _refresh_schema
agreed = self.wait_for_schema_agreement(connection, preloaded_results=preloaded_results)
File "/usr/local/lib/python2.7/dist-packages/cassandra/cluster.py", line 1862, in wait_for_schema_agreement
peers_query, local_query, timeout=timeout)
File "/usr/local/lib/python2.7/dist-packages/cassandra/connection.py", line 253, in wait_for_responses
raise ConnectionShutdown("Connection %s is already closed" % (self, ))
ConnectionShutdown: Connection <EventletConnection(39914640) 127.0.0.3:9042 (closed)> is already closed |
|
