| I have gotten the log from the application.
|
{\rtf1\ansi\ansicpg1252\cocoartf1404\cocoasubrtf130
{\fonttbl\f0\fswiss\fcharset0 Helvetica;}
{\colortbl;\red255\green255\blue255;}
\paperw11900\paperh16840\margl1440\margr1440\vieww10800\viewh8400\viewkind0
\pard\tx566\tx1133\tx1700\tx2267\tx2834\tx3401\tx3968\tx4535\tx5102\tx5669\tx6236\tx6803\pardirnatural\partightenfactor0
\f0\fs24 \cf0 Running 1 time\
\pard\tx566\tx1133\tx1700\tx2267\tx2834\tx3401\tx3968\tx4535\tx5102\tx5669\tx6236\tx6803\pardirnatural\partightenfactor0
\cf0 \
workspace_patrizio/python-driver$ python example_core.py\
2015-10-29 16:02:56,899 [DEBUG] cassandra.cluster: Connecting to cluster, contact points: ['10.20.255.191']; protocol version: 4\
2015-10-29 16:02:56,900 [DEBUG] cassandra.pool: Host 10.20.255.191 is now marked up\
2015-10-29 16:02:56,901 [DEBUG] cassandra.cluster: [control connection] Opening new connection to 10.20.255.191\
2015-10-29 16:02:56,903 [DEBUG] cassandra.connection: Not sending options message for new connection(43106448) to 10.20.255.191 because compression is disabled and a cql version was not specified\
2015-10-29 16:02:56,904 [DEBUG] cassandra.connection: Sending StartupMessage on <LibevConnection(43106448) 10.20.255.191:9042>\
2015-10-29 16:02:56,904 [DEBUG] cassandra.connection: Sent StartupMessage on <LibevConnection(43106448) 10.20.255.191:9042>\
2015-10-29 16:02:56,905 [DEBUG] cassandra.io.libevreactor: Starting libev event loop\
2015-10-29 16:02:56,958 [ERROR] cassandra.connection: Closing connection <LibevConnection(43106448) 10.20.255.191:9042> due to protocol error: code=000a [Protocol error] message="Invalid or unsupported protocol version: 4"\
2015-10-29 16:02:56,959 [DEBUG] cassandra.connection: Defuncting connection (43106448) to 10.20.255.191:\
None\
2015-10-29 16:02:56,959 [DEBUG] cassandra.io.libevreactor: Closing connection (43106448) to 10.20.255.191\
2015-10-29 16:02:56,960 [DEBUG] cassandra.io.libevreactor: Closed socket to 10.20.255.191\
2015-10-29 16:02:56,961 [DEBUG] cassandra.io.libevreactor: All Connections currently closed, event loop ended\
2015-10-29 16:02:56,970 [WARNING] cassandra.cluster: Downgrading core protocol version from 4 to 3 for 10.20.255.191\
2015-10-29 16:02:56,972 [DEBUG] cassandra.connection: Not sending options message for new connection(43107216) to 10.20.255.191 because compression is disabled and a cql version was not specified\
2015-10-29 16:02:56,973 [DEBUG] cassandra.connection: Sending StartupMessage on <LibevConnection(43107216) 10.20.255.191:9042>\
2015-10-29 16:02:56,974 [DEBUG] cassandra.connection: Sent StartupMessage on <LibevConnection(43107216) 10.20.255.191:9042>\
2015-10-29 16:02:56,974 [DEBUG] cassandra.io.libevreactor: Starting libev event loop\
2015-10-29 16:02:56,991 [DEBUG] cassandra.connection: Got ReadyMessage on new connection (43107216) from 10.20.255.191\
2015-10-29 16:02:56,992 [DEBUG] cassandra.cluster: [control connection] Established new connection <LibevConnection(43107216) 10.20.255.191:9042>, registering watchers and refreshing schema and topology\
2015-10-29 16:02:57,034 [DEBUG] cassandra.cluster: [control connection] Refreshing node list and token map using preloaded results\
2015-10-29 16:02:57,035 [INFO] cassandra.policies: Using datacenter 'datacenter1' for DCAwareRoundRobinPolicy (via host '10.20.255.191'); if incorrect, please specify a local_dc to the constructor, or limit contact points to local cluster nodes\
2015-10-29 16:02:57,036 [DEBUG] cassandra.cluster: [control connection] Finished fetching ring info\
2015-10-29 16:02:57,036 [DEBUG] cassandra.cluster: [control connection] Rebuilding token map due to topology changes\
2015-10-29 16:02:57,117 [DEBUG] cassandra.cluster: [control connection] user functions table not found\
2015-10-29 16:02:57,118 [DEBUG] cassandra.cluster: [control connection] user aggregates table not found\
2015-10-29 16:02:57,118 [DEBUG] cassandra.cluster: [control connection] Fetched schema, rebuilding metadata\
2015-10-29 16:02:57,156 [DEBUG] cassandra.cluster: Control connection created\
2015-10-29 16:02:57,159 [DEBUG] cassandra.pool: Initializing connection for host 10.20.255.191\
2015-10-29 16:02:57,162 [DEBUG] cassandra.connection: Not sending options message for new connection(43534032) to 10.20.255.191 because compression is disabled and a cql version was not specified\
2015-10-29 16:02:57,163 [DEBUG] cassandra.connection: Sending StartupMessage on <LibevConnection(43534032) 10.20.255.191:9042>\
2015-10-29 16:02:57,163 [DEBUG] cassandra.connection: Sent StartupMessage on <LibevConnection(43534032) 10.20.255.191:9042>\
2015-10-29 16:02:57,174 [DEBUG] cassandra.connection: Got ReadyMessage on new connection (43534032) from 10.20.255.191\
2015-10-29 16:02:57,180 [DEBUG] cassandra.pool: Finished initializing connection for host 10.20.255.191\
2015-10-29 16:02:57,181 [DEBUG] cassandra.cluster: Added pool for host 10.20.255.191 to session\
2015-10-29 16:02:57,181 [INFO] root: EDUARDOCOSTAALFAIA\
2015-10-29 16:02:57,182 [INFO] root: creating keyspace...\
2015-10-29 16:02:57,311 [DEBUG] cassandra.connection: Message pushed from server: <EventMessage(event_type=u'SCHEMA_CHANGE', trace_id=None, event_args=\{'keyspace': u'testkeyspace', 'change_type': u'CREATED'\}, stream_id=-1)>\
2015-10-29 16:02:57,344 [DEBUG] cassandra.cluster: Refreshing schema in response to schema change. Keyspace: testkeyspace; Table: None, Type: None, Function: None, Aggregate: None\
2015-10-29 16:02:57,344 [DEBUG] cassandra.cluster: [control connection] Waiting for schema agreement\
2015-10-29 16:02:57,362 [DEBUG] cassandra.cluster: [control connection] Schemas match\
2015-10-29 16:02:57,372 [DEBUG] cassandra.cluster: [control connection] Fetched keyspace info for testkeyspace, rebuilding metadata\
2015-10-29 16:02:57,373 [INFO] root: setting keyspace...\
2015-10-29 16:02:57,379 [INFO] root: creating table...\
2015-10-29 16:02:57,465 [DEBUG] cassandra.connection: Message pushed from server: <EventMessage(event_type=u'SCHEMA_CHANGE', trace_id=None, event_args=\{'keyspace': u'testkeyspace', 'change_type': u'CREATED', u'table': u'mytable'\}, stream_id=-1)>\
2015-10-29 16:02:57,488 [DEBUG] cassandra.cluster: Refreshing schema in response to schema change. Keyspace: testkeyspace; Table: mytable, Type: None, Function: None, Aggregate: None\
2015-10-29 16:02:57,489 [DEBUG] cassandra.cluster: [control connection] Waiting for schema agreement\
2015-10-29 16:02:57,507 [DEBUG] cassandra.cluster: [control connection] Schemas match\
2015-10-29 16:02:57,525 [DEBUG] cassandra.cluster: [control connection] Fetched table info for testkeyspace.mytable, rebuilding metadata\
2015-10-29 16:02:57,536 [INFO] root: inserting row 0\
2015-10-29 16:02:57,558 [INFO] root: inserting row 1\
2015-10-29 16:02:57,568 [INFO] root: inserting row 2\
2015-10-29 16:02:57,578 [INFO] root: inserting row 3\
2015-10-29 16:02:57,586 [INFO] root: inserting row 4\
2015-10-29 16:02:57,596 [INFO] root: inserting row 5\
2015-10-29 16:02:57,605 [INFO] root: inserting row 6\
2015-10-29 16:02:57,615 [INFO] root: inserting row 7\
2015-10-29 16:02:57,622 [INFO] root: inserting row 8\
2015-10-29 16:02:57,630 [INFO] root: inserting row 9\
2015-10-29 16:02:57,638 [INFO] root: key col1 col2\
2015-10-29 16:02:57,640 [INFO] root: --- ---- ----\
2015-10-29 16:02:57,720 [INFO] root: key5 a b\
2015-10-29 16:02:57,721 [INFO] root: key5 b b\
2015-10-29 16:02:57,722 [INFO] root: key6 a b\
2015-10-29 16:02:57,722 [INFO] root: key6 b b\
2015-10-29 16:02:57,722 [INFO] root: key0 a b\
2015-10-29 16:02:57,723 [INFO] root: key0 b b\
2015-10-29 16:02:57,723 [INFO] root: key1 a b\
2015-10-29 16:02:57,723 [INFO] root: key1 b b\
2015-10-29 16:02:57,724 [INFO] root: key9 a b\
2015-10-29 16:02:57,724 [INFO] root: key9 b b\
2015-10-29 16:02:57,725 [INFO] root: key4 a b\
2015-10-29 16:02:57,725 [INFO] root: key4 b b\
2015-10-29 16:02:57,725 [INFO] root: key8 a b\
2015-10-29 16:02:57,726 [INFO] root: key8 b b\
2015-10-29 16:02:57,726 [INFO] root: key3 a b\
2015-10-29 16:02:57,726 [INFO] root: key3 b b\
2015-10-29 16:02:57,727 [INFO] root: key7 a b\
2015-10-29 16:02:57,727 [INFO] root: key7 b b\
2015-10-29 16:02:57,727 [INFO] root: key2 a b\
2015-10-29 16:02:57,728 [INFO] root: key2 b b\
2015-10-29 16:02:57,852 [DEBUG] cassandra.connection: Message pushed from server: <EventMessage(event_type=u'SCHEMA_CHANGE', trace_id=None, event_args=\{'keyspace': u'testkeyspace', 'change_type': u'DROPPED', u'table': u'mytable'\}, stream_id=-1)>\
2015-10-29 16:02:57,853 [DEBUG] cassandra.cluster: Ignoring schedule_unique for already-scheduled task: (<bound method ControlConnection.refresh_schema of <cassandra.cluster.ControlConnection object at 0x2915e90>>, (u'testkeyspace', u'mytable', None, None, None))\
2015-10-29 16:02:58,054 [DEBUG] cassandra.connection: Message pushed from server: <EventMessage(event_type=u'SCHEMA_CHANGE', trace_id=None, event_args=\{'keyspace': u'testkeyspace', 'change_type': u'DROPPED'\}, stream_id=-1)>\
2015-10-29 16:02:58,055 [DEBUG] cassandra.cluster: Ignoring schedule_unique for already-scheduled task: (<bound method ControlConnection.refresh_schema of <cassandra.cluster.ControlConnection object at 0x2915e90>>, (u'testkeyspace', None, None, None, None))\
2015-10-29 16:02:58,065 [DEBUG] cassandra.cluster: Refreshing schema in response to schema change. Keyspace: testkeyspace; Table: None, Type: None, Function: None, Aggregate: None\
2015-10-29 16:02:58,066 [DEBUG] cassandra.cluster: [control connection] Waiting for schema agreement\
2015-10-29 16:02:58,083 [DEBUG] cassandra.cluster: [control connection] Schemas match\
2015-10-29 16:02:58,088 [DEBUG] cassandra.cluster: [control connection] Fetched keyspace info for testkeyspace, rebuilding metadata\
2015-10-29 16:02:58,132 [DEBUG] cassandra.cluster: Shutting down Cluster Scheduler\
2015-10-29 16:02:58,133 [DEBUG] cassandra.cluster: Shutting down control connection\
2015-10-29 16:02:58,134 [DEBUG] cassandra.io.libevreactor: Closing connection (43107216) to 10.20.255.191\
2015-10-29 16:02:58,134 [DEBUG] cassandra.io.libevreactor: Closed socket to 10.20.255.191\
2015-10-29 16:02:58,136 [DEBUG] cassandra.io.libevreactor: Closing connection (43534032) to 10.20.255.191\
2015-10-29 16:02:58,136 [DEBUG] cassandra.io.libevreactor: Closed socket to 10.20.255.191\
2015-10-29 16:02:58,138 [DEBUG] cassandra.io.libevreactor: Waiting for event loop thread to join...\
2015-10-29 16:02:58,139 [DEBUG] cassandra.io.libevreactor: All Connections currently closed, event loop ended\
2015-10-29 16:02:58,140 [DEBUG] cassandra.io.libevreactor: Event loop thread was joined\
2015-10-29 16:02:58,218 [DEBUG] cassandra.cluster: Shutting down Cluster Scheduler\
2015-10-29 16:02:58,219 [DEBUG] cassandra.cluster: Not executing scheduled task due to Scheduler shutdown\
\
##########################################################################\
\
Running 2 time\
\
ealfaia@apu01:~/workspace_patrizio/python-driver$ python example_core.py\
2015-10-29 16:03:40,390 [DEBUG] cassandra.cluster: Connecting to cluster, contact points: ['10.20.255.191']; protocol version: 4\
2015-10-29 16:03:40,391 [DEBUG] cassandra.pool: Host 10.20.255.191 is now marked up\
2015-10-29 16:03:40,392 [DEBUG] cassandra.cluster: [control connection] Opening new connection to 10.20.255.191\
2015-10-29 16:03:40,394 [DEBUG] cassandra.connection: Not sending options message for new connection(14196880) to 10.20.255.191 because compression is disabled and a cql version was not specified\
2015-10-29 16:03:40,395 [DEBUG] cassandra.connection: Sending StartupMessage on <LibevConnection(14196880) 10.20.255.191:9042>\
2015-10-29 16:03:40,395 [DEBUG] cassandra.connection: Sent StartupMessage on <LibevConnection(14196880) 10.20.255.191:9042>\
2015-10-29 16:03:40,396 [DEBUG] cassandra.io.libevreactor: Starting libev event loop\
2015-10-29 16:03:40,412 [ERROR] cassandra.connection: Closing connection <LibevConnection(14196880) 10.20.255.191:9042> due to protocol error: code=000a [Protocol error] message="Invalid or unsupported protocol version: 4"\
2015-10-29 16:03:40,412 [DEBUG] cassandra.connection: Defuncting connection (14196880) to 10.20.255.191:\
None\
2015-10-29 16:03:40,413 [DEBUG] cassandra.io.libevreactor: Closing connection (14196880) to 10.20.255.191\
2015-10-29 16:03:40,414 [DEBUG] cassandra.io.libevreactor: Closed socket to 10.20.255.191\
2015-10-29 16:03:40,416 [DEBUG] cassandra.io.libevreactor: All Connections currently closed, event loop ended\
2015-10-29 16:03:40,430 [WARNING] cassandra.cluster: Downgrading core protocol version from 4 to 3 for 10.20.255.191\
2015-10-29 16:03:40,432 [DEBUG] cassandra.connection: Not sending options message for new connection(14197648) to 10.20.255.191 because compression is disabled and a cql version was not specified\
2015-10-29 16:03:40,433 [DEBUG] cassandra.connection: Sending StartupMessage on <LibevConnection(14197648) 10.20.255.191:9042>\
2015-10-29 16:03:40,433 [DEBUG] cassandra.connection: Sent StartupMessage on <LibevConnection(14197648) 10.20.255.191:9042>\
2015-10-29 16:03:40,434 [DEBUG] cassandra.io.libevreactor: Starting libev event loop\
2015-10-29 16:03:40,445 [DEBUG] cassandra.connection: Got ReadyMessage on new connection (14197648) from 10.20.255.191\
2015-10-29 16:03:40,451 [DEBUG] cassandra.cluster: [control connection] Established new connection <LibevConnection(14197648) 10.20.255.191:9042>, registering watchers and refreshing schema and topology\
2015-10-29 16:03:40,474 [DEBUG] cassandra.cluster: [control connection] Refreshing node list and token map using preloaded results\
2015-10-29 16:03:40,475 [INFO] cassandra.policies: Using datacenter 'datacenter1' for DCAwareRoundRobinPolicy (via host '10.20.255.191'); if incorrect, please specify a local_dc to the constructor, or limit contact points to local cluster nodes\
2015-10-29 16:03:40,476 [DEBUG] cassandra.cluster: [control connection] Finished fetching ring info\
2015-10-29 16:03:40,476 [DEBUG] cassandra.cluster: [control connection] Rebuilding token map due to topology changes\
2015-10-29 16:03:42,483 [DEBUG] cassandra.io.libevreactor: Closing connection (14197648) to 10.20.255.191\
2015-10-29 16:03:42,484 [DEBUG] cassandra.io.libevreactor: Closed socket to 10.20.255.191\
2015-10-29 16:03:42,484 [WARNING] cassandra.cluster: [control connection] Error connecting to 10.20.255.191:\
Traceback (most recent call last):\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 2117, in _reconnect_internal\
return self._try_connect(host)\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 2164, in _try_connect\
self._refresh_schema(connection, preloaded_results=shared_results, schema_agreement_wait=-1)\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 2343, in _refresh_schema\
responses = connection.wait_for_responses(*queries, timeout=self._timeout, fail_on_error=False)\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/connection.py", line 438, in wait_for_responses\
return waiter.deliver(timeout)\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/connection.py", line 839, in deliver\
raise OperationTimedOut()\
OperationTimedOut: errors=None, last_host=None\
2015-10-29 16:03:42,485 [DEBUG] cassandra.io.libevreactor: All Connections currently closed, event loop ended\
2015-10-29 16:03:42,492 [ERROR] cassandra.cluster: Control connection failed to connect, shutting down Cluster:\
Traceback (most recent call last):\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 840, in connect\
self.control_connection.connect()\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 2091, in connect\
self._set_new_connection(self._reconnect_internal())\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 2126, in _reconnect_internal\
raise NoHostAvailable("Unable to connect to any servers", errors)\
NoHostAvailable: ('Unable to connect to any servers', \{'10.20.255.191': OperationTimedOut('errors=None, last_host=None',)\})\
2015-10-29 16:03:42,494 [DEBUG] cassandra.cluster: Shutting down Cluster Scheduler\
2015-10-29 16:03:42,495 [DEBUG] cassandra.cluster: Shutting down control connection\
Traceback (most recent call last):\
2015-10-29 16:03:42,495 [DEBUG] cassandra.cluster: Not executing scheduled task due to Scheduler shutdown\
File "example_core.py", line 129, in <module>\
main()\
File "example_core.py", line 76, in main\
session = get_session()\
File "example_core.py", line 41, in get_session\
session = cluster.connect()\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 840, in connect\
self.control_connection.connect()\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 2091, in connect\
self._set_new_connection(self._reconnect_internal())\
File "/home/ealfaia/workspace_patrizio/python-driver/cassandra/cluster.py", line 2126, in _reconnect_internal\
raise NoHostAvailable("Unable to connect to any servers", errors)\
cassandra.cluster.NoHostAvailable: ('Unable to connect to any servers', \{'10.20.255.191': OperationTimedOut('errors=None, last_host=None',)\})\
2015-10-29 16:03:42,502 [DEBUG] cassandra.io.libevreactor: Waiting for event loop thread to join...\
2015-10-29 16:03:42,503 [DEBUG] cassandra.io.libevreactor: Event loop thread was joined\
2015-10-29 16:03:42,503 [DEBUG] cassandra.cluster: Shutting down Cluster Scheduler\
2015-10-29 16:03:42,504 [DEBUG] cassandra.cluster: Not executing scheduled task due to Scheduler shutdown}
The cassandra system.log would be more useful
When Cassandra starts rejecting or dropping tcp connections, try to connect using cqlsh, and check the logs for indication that it’s failing.
I am using cassandra standalone, the machine is up, I was monitoring the cassandra seeing the system.log but I didn’t see anything wrong.
I’ve captured the flow of packets using wireshark and I’ve seen that the cassandra server is reset the connection with the client. I am sending the python app which I am using.
|
