{"action":"created","issue":{"url":"https://api.github.com/repos/scylladb/scylla/issues/480","labels_url":"https://api.github.com/repos/scylladb/scylla/issues/480/labels{/name}","comments_url":"https://api.github.com/repos/scylladb/scylla/issues/480/comments","events_url":"https://api.github.com/repos/scylladb/scylla/issues/480/events","html_url":"https://github.com/scylladb/scylla/issues/480","id":112524150,"number":480,"title":"DTEST consistency_test.py:TestConsistency.short_read_reversed_test fails","user":{"login":"slivne","id":3465480,"avatar_url":"https://avatars.githubusercontent.com/u/3465480?v=3","gravatar_id":"","url":"https://api.github.com/users/slivne","html_url":"https://github.com/slivne","followers_url":"https://api.github.com/users/slivne/followers","following_url":"https://api.github.com/users/slivne/following{/other_user}","gists_url":"https://api.github.com/users/slivne/gists{/gist_id}","starred_url":"https://api.github.com/users/slivne/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/slivne/subscriptions","organizations_url":"https://api.github.com/users/slivne/orgs","repos_url":"https://api.github.com/users/slivne/repos","events_url":"https://api.github.com/users/slivne/events{/privacy}","received_events_url":"https://api.github.com/users/slivne/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/scylladb/scylla/labels/bug","name":"bug","color":"eb6420"}],"state":"open","locked":false,"assignee":{"login":"gleb-cloudius","id":6554938,"avatar_url":"https://avatars.githubusercontent.com/u/6554938?v=3","gravatar_id":"","url":"https://api.github.com/users/gleb-cloudius","html_url":"https://github.com/gleb-cloudius","followers_url":"https://api.github.com/users/gleb-cloudius/followers","following_url":"https://api.github.com/users/gleb-cloudius/following{/other_user}","gists_url":"https://api.github.com/users/gleb-cloudius/gists{/gist_id}","starred_url":"https://api.github.com/users/gleb-cloudius/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gleb-cloudius/subscriptions","organizations_url":"https://api.github.com/users/gleb-cloudius/orgs","repos_url":"https://api.github.com/users/gleb-cloudius/repos","events_url":"https://api.github.com/users/gleb-cloudius/events{/privacy}","received_events_url":"https://api.github.com/users/gleb-cloudius/received_events","type":"User","site_admin":false},"milestone":null,"comments":7,"created_at":"2015-10-21T06:59:37Z","updated_at":"2015-10-21T08:28:05Z","closed_at":null,"body":"using \r\n\r\nMerge: 93c1035 02732f1\r\nAuthor: Avi Kivity <avi@scylladb.com>\r\nDate:   Tue Oct 20 17:36:57 2015 +0300\r\n\r\n    Merge \"Flusing of CF:s without replay positions\" from Calle\r\n    \r\n    \"Fixes: #469\r\n    \r\n    We occasionally generate memtables that are not empty, yet have no\r\n    high replay_position set. (Typical case is CL replay, but apparently\r\n    there are others).\r\n    \r\n    Moreover, we can do this repeatedly, and thus get caught in the flush\r\n    queue ordering restrictions.\r\n    \r\n    Solve this by treating a flush without replay_position as a flush at the\r\n    highest running position, i.e. \"last\" in queue. Note that this will not\r\n    affect the actual flush operation, nor CL callbacks, only anyone waiting\r\n    for the operation(s) to complete.\r\n    \r\n    To do this, the flush_queue had its restrictions eased, and some introspection\r\n    methods added.\"\r\n\r\n\r\n```\r\npkill -9 scylla;  rm -Rf ~/.dtest/*;KEEP_TEST_DIR=true nosetests -v -s consistency_test.py:TestConsistency.short_read_reversed_test\r\nFAIL\r\n\r\n======================================================================\r\nFAIL: short_read_reversed_test (consistency_test.TestConsistency)\r\n----------------------------------------------------------------------\r\nTraceback (most recent call last):\r\n  File \"/home/shlomi/urchin-dtest/consistency_test.py\", line 791, in short_read_reversed_test\r\n    assert res[i][1] == 'value%d' % (5-i), 'Expecting value%d, got %s (%s)' % (5-i, res[i][1], str(res))\r\nAssertionError: Expecting value5, got value2 ([Row(c=u'c000002', v=u'value2'), Row(c=u'c000001', v=u'value1'), Row(c=u'c000000', v=u'value0')])\r\n-------------------- >> begin captured logging << --------------------\r\ndtest: DEBUG: cluster ccm directory: /home/shlomi/.dtest/dtest-KuMZzV\r\ncassandra.cluster: WARNING: Host 127.0.0.1 has been marked down\r\ncassandra.pool: WARNING: Error attempting to reconnect to 127.0.0.1, scheduling retry in 2.0 seconds: [Errno 111] Tried connecting to [('127.0.0.1', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Failed to create connection pool for new host 127.0.0.1:\r\nTraceback (most recent call last):\r\n  File \"cassandra/cluster.py\", line 1831, in cassandra.cluster.Session.add_or_renew_pool.run_add_or_renew_pool (cassandra/cluster.c:31324)\r\n    new_pool = HostConnection(host, distance, self)\r\n  File \"cassandra/pool.py\", line 295, in cassandra.pool.HostConnection.__init__ (cassandra/pool.c:6160)\r\n    self._connection = session.cluster.connection_factory(host.address)\r\n  File \"cassandra/cluster.py\", line 785, in cassandra.cluster.Cluster.connection_factory (cassandra/cluster.c:9335)\r\n    return self.connection_class.factory(address, self.connect_timeout, *args, **kwargs)\r\n  File \"cassandra/connection.py\", line 304, in cassandra.connection.Connection.factory (cassandra/connection.c:5114)\r\n    conn = cls(host, *args, **kwargs)\r\n  File \"/usr/lib64/python2.7/site-packages/cassandra/io/libevreactor.py\", line 264, in __init__\r\n    self._connect_socket()\r\n  File \"cassandra/connection.py\", line 338, in cassandra.connection.Connection._connect_socket (cassandra/connection.c:6246)\r\n    raise socket.error(sockerr.errno, \"Tried connecting to %s. Last error: %s\" % ([a[4] for a in addresses], sockerr.strerror or sockerr))\r\nerror: [Errno 111] Tried connecting to [('127.0.0.1', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Host 127.0.0.1 has been marked down\r\ncassandra.cluster: WARNING: Host 127.0.0.2 has been marked down\r\ncassandra.pool: WARNING: Error attempting to reconnect to 127.0.0.2, scheduling retry in 2.0 seconds: [Errno 111] Tried connecting to [('127.0.0.2', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Failed to create connection pool for new host 127.0.0.2:\r\nTraceback (most recent call last):\r\n  File \"cassandra/cluster.py\", line 1831, in cassandra.cluster.Session.add_or_renew_pool.run_add_or_renew_pool (cassandra/cluster.c:31324)\r\n    new_pool = HostConnection(host, distance, self)\r\n  File \"cassandra/pool.py\", line 295, in cassandra.pool.HostConnection.__init__ (cassandra/pool.c:6160)\r\n    self._connection = session.cluster.connection_factory(host.address)\r\n  File \"cassandra/cluster.py\", line 785, in cassandra.cluster.Cluster.connection_factory (cassandra/cluster.c:9335)\r\n    return self.connection_class.factory(address, self.connect_timeout, *args, **kwargs)\r\n  File \"cassandra/connection.py\", line 304, in cassandra.connection.Connection.factory (cassandra/connection.c:5114)\r\n    conn = cls(host, *args, **kwargs)\r\n  File \"/usr/lib64/python2.7/site-packages/cassandra/io/libevreactor.py\", line 264, in __init__\r\n    self._connect_socket()\r\n  File \"cassandra/connection.py\", line 338, in cassandra.connection.Connection._connect_socket (cassandra/connection.c:6246)\r\n    raise socket.error(sockerr.errno, \"Tried connecting to %s. Last error: %s\" % ([a[4] for a in addresses], sockerr.strerror or sockerr))\r\nerror: [Errno 111] Tried connecting to [('127.0.0.2', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Host 127.0.0.2 has been marked down\r\ncassandra.cluster: WARNING: Host 127.0.0.2 has been marked down\r\ncassandra.cluster: WARNING: [control connection] Error connecting to 127.0.0.3:\r\nTraceback (most recent call last):\r\n  File \"cassandra/cluster.py\", line 2114, in cassandra.cluster.ControlConnection._reconnect_internal (cassandra/cluster.c:37551)\r\n    return self._try_connect(host)\r\n  File \"cassandra/cluster.py\", line 2134, in cassandra.cluster.ControlConnection._try_connect (cassandra/cluster.c:38028)\r\n    connection = self._cluster.connection_factory(host.address, is_control_connection=True)\r\n  File \"cassandra/cluster.py\", line 785, in cassandra.cluster.Cluster.connection_factory (cassandra/cluster.c:9335)\r\n    return self.connection_class.factory(address, self.connect_timeout, *args, **kwargs)\r\n  File \"cassandra/connection.py\", line 304, in cassandra.connection.Connection.factory (cassandra/connection.c:5114)\r\n    conn = cls(host, *args, **kwargs)\r\n  File \"/usr/lib64/python2.7/site-packages/cassandra/io/libevreactor.py\", line 264, in __init__\r\n    self._connect_socket()\r\n  File \"cassandra/connection.py\", line 338, in cassandra.connection.Connection._connect_socket (cassandra/connection.c:6246)\r\n    raise socket.error(sockerr.errno, \"Tried connecting to %s. Last error: %s\" % ([a[4] for a in addresses], sockerr.strerror or sockerr))\r\nerror: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Host 127.0.0.3 has been marked down\r\ncassandra.pool: WARNING: Error attempting to reconnect to 127.0.0.3, scheduling retry in 2.0 seconds: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Host 127.0.0.3 has been marked down\r\ncassandra.cluster: WARNING: Host 127.0.0.3 has been marked down\r\ncassandra.cluster: WARNING: [control connection] Error connecting to 127.0.0.3:\r\nTraceback (most recent call last):\r\n  File \"cassandra/cluster.py\", line 2114, in cassandra.cluster.ControlConnection._reconnect_internal (cassandra/cluster.c:37551)\r\n    return self._try_connect(host)\r\n  File \"cassandra/cluster.py\", line 2134, in cassandra.cluster.ControlConnection._try_connect (cassandra/cluster.c:38028)\r\n    connection = self._cluster.connection_factory(host.address, is_control_connection=True)\r\n  File \"cassandra/cluster.py\", line 785, in cassandra.cluster.Cluster.connection_factory (cassandra/cluster.c:9335)\r\n    return self.connection_class.factory(address, self.connect_timeout, *args, **kwargs)\r\n  File \"cassandra/connection.py\", line 304, in cassandra.connection.Connection.factory (cassandra/connection.c:5114)\r\n    conn = cls(host, *args, **kwargs)\r\n  File \"/usr/lib64/python2.7/site-packages/cassandra/io/libevreactor.py\", line 264, in __init__\r\n    self._connect_socket()\r\n  File \"cassandra/connection.py\", line 338, in cassandra.connection.Connection._connect_socket (cassandra/connection.c:6246)\r\n    raise socket.error(sockerr.errno, \"Tried connecting to %s. Last error: %s\" % ([a[4] for a in addresses], sockerr.strerror or sockerr))\r\nerror: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\ncassandra.pool: WARNING: Error attempting to reconnect to 127.0.0.3, scheduling retry in 2.0 seconds: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\ncassandra.pool: WARNING: Error attempting to reconnect to 127.0.0.3, scheduling retry in 2.0 seconds: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\ncassandra.pool: WARNING: Error attempting to reconnect to 127.0.0.3, scheduling retry in 4.0 seconds: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Failed to create connection pool for new host 127.0.0.3:\r\nTraceback (most recent call last):\r\n  File \"cassandra/cluster.py\", line 1831, in cassandra.cluster.Session.add_or_renew_pool.run_add_or_renew_pool (cassandra/cluster.c:31324)\r\n    new_pool = HostConnection(host, distance, self)\r\n  File \"cassandra/pool.py\", line 295, in cassandra.pool.HostConnection.__init__ (cassandra/pool.c:6160)\r\n    self._connection = session.cluster.connection_factory(host.address)\r\n  File \"cassandra/cluster.py\", line 785, in cassandra.cluster.Cluster.connection_factory (cassandra/cluster.c:9335)\r\n    return self.connection_class.factory(address, self.connect_timeout, *args, **kwargs)\r\n  File \"cassandra/connection.py\", line 304, in cassandra.connection.Connection.factory (cassandra/connection.c:5114)\r\n    conn = cls(host, *args, **kwargs)\r\n  File \"/usr/lib64/python2.7/site-packages/cassandra/io/libevreactor.py\", line 264, in __init__\r\n    self._connect_socket()\r\n  File \"cassandra/connection.py\", line 338, in cassandra.connection.Connection._connect_socket (cassandra/connection.c:6246)\r\n    raise socket.error(sockerr.errno, \"Tried connecting to %s. Last error: %s\" % ([a[4] for a in addresses], sockerr.strerror or sockerr))\r\nerror: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\ncassandra.cluster: WARNING: Host 127.0.0.3 has been marked down\r\ncassandra.pool: WARNING: Error attempting to reconnect to 127.0.0.3, scheduling retry in 4.0 seconds: [Errno 111] Tried connecting to [('127.0.0.3', 9042)]. Last error: Connection refused\r\n--------------------- >> end captured logging << ---------------------\r\n\r\n----------------------------------------------------------------------\r\nRan 1 test in 110.853s\r\n\r\nFAILED (failures=1)\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/scylladb/scylla/issues/comments/149815789","html_url":"https://github.com/scylladb/scylla/issues/480#issuecomment-149815789","issue_url":"https://api.github.com/repos/scylladb/scylla/issues/480","id":149815789,"user":{"login":"slivne","id":3465480,"avatar_url":"https://avatars.githubusercontent.com/u/3465480?v=3","gravatar_id":"","url":"https://api.github.com/users/slivne","html_url":"https://github.com/slivne","followers_url":"https://api.github.com/users/slivne/followers","following_url":"https://api.github.com/users/slivne/following{/other_user}","gists_url":"https://api.github.com/users/slivne/gists{/gist_id}","starred_url":"https://api.github.com/users/slivne/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/slivne/subscriptions","organizations_url":"https://api.github.com/users/slivne/orgs","repos_url":"https://api.github.com/users/slivne/repos","events_url":"https://api.github.com/users/slivne/events{/privacy}","received_events_url":"https://api.github.com/users/slivne/received_events","type":"User","site_admin":false},"created_at":"2015-10-21T08:28:05Z","updated_at":"2015-10-21T08:28:05Z","body":"The code itself of the test is very simple\r\n\r\nIt create a cluster of 3 nodes with rf=3, inserts 9 values (0-8)\r\n- it stops a node deletes value 8 starts stopped node again\r\n- it stops a node deletes value 7 starts stopped node again\r\n- it stops a node deletes value 6 starts stopped node again\r\n- it does a select order by desc limit 3\r\n- it checks it got back 3 values - it checks the values and we do not adhere to the order by.\r\n\r\n\r\n```\r\n    def short_read_reversed_test(self):\r\n        cluster = self.cluster\r\n\r\n        # Disable hinted handoff and set batch commit log so this doesn't\r\n        # interfer with the test\r\n        cluster.set_configuration_options(values={ 'hinted_handoff_enabled' : False}, batch_commitlog=True)\r\n\r\n        cluster.populate(3).start(wait_other_notice=True,jvm_args=['--default-log-level','trace'])\r\n        node1, node2, node3 = cluster.nodelist()\r\n\r\n        cursor = self.patient_cql_connection(node1)\r\n        self.create_ks(cursor, 'ks', 3)\r\n        self.create_cf(cursor, 'cf', read_repair=0.0)\r\n        # insert 9 columns in one row\r\n        insert_columns(self, cursor, 0, 9)\r\n\r\n        # Deleting 3 last columns with a different node dead each time\r\n        self.stop_delete_and_restart(1, 6)\r\n        self.stop_delete_and_restart(2, 7)\r\n        self.stop_delete_and_restart(3, 8)\r\n\r\n        # Query 3 firsts columns\r\n        cursor = self.patient_cql_connection(node1, 'ks')\r\n        query = SimpleStatement('SELECT c, v FROM cf WHERE key=\\'k0\\' ORDER BY c DESC LIMIT 3', consistency_level=ConsistencyLevel.QUORUM)\r\n        rows = cursor.execute(query)\r\n        res = rows\r\n        assert len(res) == 3, 'Expecting 3 values, got %d (%s)' % (len(res), str(res))\r\n        # value 6, 7 and 8 have been deleted\r\n        for i in xrange(0, 3):\r\n            assert res[i][1] == 'value%d' % (5-i), 'Expecting value%d, got %s (%s)' % (5-i, res[i][1], str(res))\r\n```\r\n\r\nthere is no failure/core/crash.\r\n\r\nthe issue is that the short read does not apply the ORDER BY DESC limit\r\n\r\ninstead of returning values 5,4,3 it returns values 2,1,0 and its not what is expected.\r\n\r\n\r\n\r\n"}}