[ https://issues.apache.org/jira/browse/CASSANDRA-12441?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Russ Hatch resolved CASSANDRA-12441. ------------------------------------ Resolution: Not A Problem > dtest failure in > upgrade_tests.upgrade_through_versions_test.TestUpgrade_current_2_2_x_To_indev_3_0_x.rolling_upgrade_with_internode_ssl_test > --------------------------------------------------------------------------------------------------------------------------------------------- > > Key: CASSANDRA-12441 > URL: https://issues.apache.org/jira/browse/CASSANDRA-12441 > Project: Cassandra > Issue Type: Test > Reporter: Craig Kodman > Assignee: DS Test Eng > Labels: dtest > Attachments: node1.log, node1_debug.log, node1_gc.log, node2.log, > node2_debug.log, node2_gc.log, node3.log, node3_debug.log, node3_gc.log > > > example failure: > http://cassci.datastax.com/job/cassandra-3.0_large_dtest/20/testReport/upgrade_tests.upgrade_through_versions_test/TestUpgrade_current_2_2_x_To_indev_3_0_x/rolling_upgrade_with_internode_ssl_test > {code} > Error Message > Ran out of time waiting for queue size (1) to be 'le' to 0. Aborting. > -------------------- >> begin captured logging << -------------------- > dtest: DEBUG: Upgrade test beginning, setting CASSANDRA_VERSION to 2.2.7, and > jdk to 8. (Prior values will be restored after test). > dtest: DEBUG: cluster ccm directory: /tmp/dtest-U_C4o2 > ccm: DEBUG: Log-watching thread starting. > dtest: DEBUG: Done setting configuration options: > { 'initial_token': None, > 'num_tokens': '32', > 'phi_convict_threshold': 5, > 'range_request_timeout_in_ms': 10000, > 'read_request_timeout_in_ms': 10000, > 'request_timeout_in_ms': 10000, > 'truncate_request_timeout_in_ms': 10000, > 'write_request_timeout_in_ms': 10000} > dtest: DEBUG: Setting extra configuration options: > { 'partitioner': 'org.apache.cassandra.dht.Murmur3Partitioner'} > dtest: DEBUG: Versions to test (<class > 'upgrade_tests.upgrade_through_versions_test.TestUpgrade_current_2_2_x_To_indev_3_0_x'>): > ['2.2.7', 'git:465def8e295b453dc22430dc4bb7039f6921151e'] > dtest: DEBUG: ***using internode ssl*** > dtest: DEBUG: generating keystore.jks in [/tmp/dtest-U_C4o2] > dtest: DEBUG: exporting cert from keystore.jks in [/tmp/dtest-U_C4o2] > dtest: DEBUG: importing cert into truststore.jks in [/tmp/dtest-U_C4o2] > dtest: DEBUG: Creating cluster (2.2.7) > dtest: DEBUG: Current upgrade path: ['***2.2.7***', > 'git:465def8e295b453dc22430dc4bb7039f6921151e'] > dtest: DEBUG: rows written (but not verified) queue size is at 417, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 442, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 474, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 503, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 536, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 565, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 597, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 634, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 663, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size is at 690, target is > to reach 'ge' 5000 > dtest: DEBUG: rows written (but not verified) queue size (5044) is 'ge' to > 5000. Continuing. > dtest: DEBUG: counters incremented (but not verified) queue size (5042) is > 'ge' to 5000. Continuing. > dtest: DEBUG: Upgrading ['node1'] to > git:465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: JAVA_HOME: /usr/lib/jvm/jdk1.8.0_51 > dtest: DEBUG: Shutting down node: node1 > ccm: INFO: Fetching Cassandra updates... > dtest: DEBUG: Set new cassandra dir for node1: > /home/automaton/.ccm/repository/gitCOLON465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: Starting node1 on new version > (git:465def8e295b453dc22430dc4bb7039f6921151e) > dtest: DEBUG: Successfully upgraded 1 of 3 nodes to > git:465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: Upgrading ['node2'] to > git:465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: JAVA_HOME: /usr/lib/jvm/jdk1.8.0_51 > dtest: DEBUG: Shutting down node: node2 > ccm: INFO: Fetching Cassandra updates... > dtest: DEBUG: Set new cassandra dir for node2: > /home/automaton/.ccm/repository/gitCOLON465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: Starting node2 on new version > (git:465def8e295b453dc22430dc4bb7039f6921151e) > dtest: DEBUG: Successfully upgraded 2 of 3 nodes to > git:465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: Upgrading ['node3'] to > git:465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: JAVA_HOME: /usr/lib/jvm/jdk1.8.0_51 > dtest: DEBUG: Shutting down node: node3 > ccm: INFO: Fetching Cassandra updates... > dtest: DEBUG: Set new cassandra dir for node3: > /home/automaton/.ccm/repository/gitCOLON465def8e295b453dc22430dc4bb7039f6921151e > dtest: DEBUG: Starting node3 on new version > (git:465def8e295b453dc22430dc4bb7039f6921151e) > dtest: DEBUG: Successfully upgraded 3 of 3 nodes to > git:465def8e295b453dc22430dc4bb7039f6921151e > ccm: INFO: Fetching Cassandra updates... > dtest: DEBUG: writes pending verification queue size is at 46041, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 46013, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45983, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45952, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45922, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45893, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45862, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45829, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45801, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 45771, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36705, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36675, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36649, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36620, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36592, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36564, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36536, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36507, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36474, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 36442, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27707, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27679, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27650, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27623, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27591, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27559, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27532, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27504, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27474, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 27441, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 18630, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 18601, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 18571, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 18543, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 18512, target is > to reach 'le' 0 > dtest: DEBUG: writes pending verification queue size is at 18484, target is > to reach 'le' 0 > {code} > {code} > Stacktrace > File "/usr/lib/python2.7/unittest/case.py", line 329, in run > testMethod() > File > "/home/automaton/cassandra-dtest/upgrade_tests/upgrade_through_versions_test.py", > line 298, in rolling_upgrade_with_internode_ssl_test > self.upgrade_scenario(rolling=True, internode_ssl=True) > File > "/home/automaton/cassandra-dtest/upgrade_tests/upgrade_through_versions_test.py", > line 366, in upgrade_scenario > self._wait_until_queue_condition('counters pending verification', > incr_verify_queue, operator.le, 0, max_wait_s=1200) > File > "/home/automaton/cassandra-dtest/upgrade_tests/upgrade_through_versions_test.py", > line 551, in _wait_until_queue_condition > raise RuntimeError("Ran out of time waiting for queue size ({}) to be > '{}' to {}. Aborting.".format(qsize, opfunc.__name__, required_len)) > "Ran out of time waiting for queue size (1) to be 'le' to 0. > Aborting.\n-------------------- >> begin captured logging << > --------------------\ndtest: DEBUG: Upgrade test beginning, setting > CASSANDRA_VERSION to 2.2.7, and jdk to 8. (Prior values will be restored > after test).\ndtest: DEBUG: cluster ccm directory: /tmp/dtest-U_C4o2\nccm: > DEBUG: Log-watching thread starting.\ndtest: DEBUG: Done setting > configuration options:\n{ 'initial_token': None,\n 'num_tokens': '32',\n > 'phi_convict_threshold': 5,\n 'range_request_timeout_in_ms': 10000,\n > 'read_request_timeout_in_ms': 10000,\n 'request_timeout_in_ms': 10000,\n > 'truncate_request_timeout_in_ms': 10000,\n > 'write_request_timeout_in_ms': 10000}\ndtest: DEBUG: Setting extra > configuration options:\n{ 'partitioner': > 'org.apache.cassandra.dht.Murmur3Partitioner'}\ndtest: DEBUG: Versions to > test (<class > 'upgrade_tests.upgrade_through_versions_test.TestUpgrade_current_2_2_x_To_indev_3_0_x'>): > ['2.2.7', 'git:465def8e295b453dc22430dc4bb7039f6921151e']\ndtest: DEBUG: > ***using internode ssl***\ndtest: DEBUG: generating keystore.jks in > [/tmp/dtest-U_C4o2]\ndtest: DEBUG: exporting cert from keystore.jks in > [/tmp/dtest-U_C4o2]\ndtest: DEBUG: importing cert into truststore.jks in > [/tmp/dtest-U_C4o2]\ndtest: DEBUG: Creating cluster (2.2.7)\ndtest: DEBUG: > Current upgrade path: ['***2.2.7***', > 'git:465def8e295b453dc22430dc4bb7039f6921151e']\ndtest: DEBUG: rows written > (but not verified) queue size is at 417, target is to reach 'ge' 5000\ndtest: > DEBUG: rows written (but not verified) queue size is at 442, target is to > reach 'ge' 5000\ndtest: DEBUG: rows written (but not verified) queue size is > at 474, target is to reach 'ge' 5000\ndtest: DEBUG: rows written (but not > verified) queue size is at 503, target is to reach 'ge' 5000\ndtest: DEBUG: > rows written (but not verified) queue size is at 536, target is to reach 'ge' > 5000\ndtest: DEBUG: rows written (but not verified) queue size is at 565, > target is to reach 'ge' 5000\ndtest: DEBUG: rows written (but not verified) > queue size is at 597, target is to reach 'ge' 5000\ndtest: DEBUG: rows > written (but not verified) queue size is at 634, target is to reach 'ge' > 5000\ndtest: DEBUG: rows written (but not verified) queue size is at 663, > target is to reach 'ge' 5000\ndtest: DEBUG: rows written (but not verified) > queue size is at 690, target is to reach 'ge' 5000\ndtest: DEBUG: rows > written (but not verified) queue size (5044) is 'ge' to 5000. > Continuing.\ndtest: DEBUG: counters incremented (but not verified) queue size > (5042) is 'ge' to 5000. Continuing.\ndtest: DEBUG: Upgrading ['node1'] to > git:465def8e295b453dc22430dc4bb7039f6921151e\ndtest: DEBUG: JAVA_HOME: > /usr/lib/jvm/jdk1.8.0_51\ndtest: DEBUG: Shutting down node: node1\nccm: INFO: > Fetching Cassandra updates...\ndtest: DEBUG: Set new cassandra dir for node1: > /home/automaton/.ccm/repository/gitCOLON465def8e295b453dc22430dc4bb7039f6921151e\ndtest: > DEBUG: Starting node1 on new version > (git:465def8e295b453dc22430dc4bb7039f6921151e)\ndtest: DEBUG: Successfully > upgraded 1 of 3 nodes to git:465def8e295b453dc22430dc4bb7039f6921151e\ndtest: > DEBUG: Upgrading ['node2'] to > git:465def8e295b453dc22430dc4bb7039f6921151e\ndtest: DEBUG: JAVA_HOME: > /usr/lib/jvm/jdk1.8.0_51\ndtest: DEBUG: Shutting down node: node2\nccm: INFO: > Fetching Cassandra updates...\ndtest: DEBUG: Set new cassandra dir for node2: > /home/automaton/.ccm/repository/gitCOLON465def8e295b453dc22430dc4bb7039f6921151e\ndtest: > DEBUG: Starting node2 on new version > (git:465def8e295b453dc22430dc4bb7039f6921151e)\ndtest: DEBUG: Successfully > upgraded 2 of 3 nodes to git:465def8e295b453dc22430dc4bb7039f6921151e\ndtest: > DEBUG: Upgrading ['node3'] to > git:465def8e295b453dc22430dc4bb7039f6921151e\ndtest: DEBUG: JAVA_HOME: > /usr/lib/jvm/jdk1.8.0_51\ndtest: DEBUG: Shutting down node: node3\nccm: INFO: > Fetching Cassandra updates...\ndtest: DEBUG: Set new cassandra dir for node3: > /home/automaton/.ccm/repository/gitCOLON465def8e295b453dc22430dc4bb7039f6921151e\ndtest: > DEBUG: Starting node3 on new version > (git:465def8e295b453dc22430dc4bb7039f6921151e)\ndtest: DEBUG: Successfully > upgraded 3 of 3 nodes to git:465def8e295b453dc22430dc4bb7039f6921151e\nccm: > INFO: Fetching Cassandra updates...\ndtest: DEBUG: writes pending > verification queue size is at 46041, target is to reach 'le' 0\ndtest: DEBUG: > writes pending verification queue size is at 46013, target is to reach 'le' > 0\ndtest: DEBUG: writes pending verification queue size is at 45983, target > is to reach 'le' 0\ndtest: DEBUG: writes pending verification queue size is > at 45952, target is to reach 'le' 0\ndtest: DEBUG: writes pending > verification queue size is at 45922, target is to reach 'le' 0\ndtest: DEBUG: > writes pending verification queue size is at 45893, target is to reach 'le' > 0\ndtest: DEBUG: writes pending verification queue size is at 45862, target > is to reach 'le' 0\ndtest: DEBUG: writes pending verification queue size is > at 45829, target is to reach 'le' 0\ndtest: DEBUG: writes pending > verification queue size is at 45801, target is to reach 'le' 0\ndtest: DEBUG: > writes pending verification queue size is at 45771, target is to reach 'le' > 0\ndtest: DEBUG: writes pending verification queue size is at 36705, target > is to reach 'le' 0\ndtest: DEBUG: writes pending verification queue size is > at 36675, target is to reach 'le' 0\ndtest: DEBUG: writes pending > verification queue size is at 36649, target is to reach 'le' 0\ndtest: DEBUG: > writes pending verification queue size is at 36620, target is to reach 'le' > 0\ndtest: DEBUG: writes pending verification queue size is at 36592, target > is to reach 'le' 0\ndtest: DEBUG: writes pending verification queue size is > at 36564, target is to reach 'le' 0\ndtest: DEBUG: writes pending > verification queue size is at 36536, target is to reach 'le' 0\ndtest: DEBUG: > writes pending verification queue size is at 36507, target is to reach 'le' > 0\ndtest: DEBUG: writes pending verification queue size is at 36474, target > is to reach 'le' 0\ndtest: DEBUG: writes pending verification queue size is > at 36442, target is to reach 'le' 0\ndtest: DEBUG: writes pending > verification queue size is at 27707, target is to reach 'le' 0\ndtest: DEBUG: > writes pending verification queue size is at 27679, target is to reach 'le' > 0\ndtest: DEBUG: writes pending verification queue size is at 27650, target > is to reach 'le' 0\ndtest: DEBUG: writes pending verification queue size is > at 27623, target is to reach 'le' 0\ndtest: DEBUG: writes pending > verification queue size is at 27591, target is to reach 'le' 0\ndtest: DEBUG: > writes pending verification queue size is at 27559, target is to reach 'le' > 0\ndtest: DEBUG: writes pending verification queue size is at 27532, target > is to reach 'le' 0\ndtest: DEBUG: writes pending verification queue size is > at 27504, target is to reach 'le' 0\ndtest: DEBUG > {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)