[IMPALA-4348] TestRPCTimeout.test_execplanfragment_timeout fails in exhaustive

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: Impala 2.7.0
• Fix Version/s: Impala 2.8.0
• Component/s: Distributed Exec
• Labels: broken-build
• Target Version: Impala 2.8.0
• Assignee: Henry Robinson
• Reporter: Jim Apple
• Created: 24/Oct/16 15:48
• Updated: 28/Oct/16 20:05
• Resolved: 28/Oct/16 20:05

Description

The following is a test failure I saw when running the tests in exhaustive mode:

 TestRPCTimeout.test_execplanfragment_timeout[exec_option: {'disable_codegen': False, 'abort_on_error': 1, 'exec_single_node_rows_threshold': 0, 'batch_size': 0, 'num_nodes': 0} | table_format: text/none] 

self = <test_rpc_timeout.TestRPCTimeout object at 0x5f4ffd0>
vector = <tests.common.test_vector.TestVector object at 0x6424a10>

    @pytest.mark.execute_serially
    @CustomClusterTestSuite.with_args("--backend_client_rpc_timeout_ms=1000"
        " --fault_injection_rpc_delay_ms=3000 --fault_injection_rpc_type=1"
        " --datastream_sender_timeout_ms=30000")
    def test_execplanfragment_timeout(self, vector):
      for i in range(3):
        ex= self.execute_query_expect_failure(self.client, self.TEST_QUERY)
        assert "RPC recv timed out" in str(ex)
      verifiers = [ MetricVerifier(i.service) for i in ImpalaCluster().impalads ]
    
      for v in verifiers:
>       v.wait_for_metric("impala-server.num-fragments-in-flight", 0)

custom_cluster/test_rpc_timeout.py:90: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
verifiers/metric_verifier.py:59: in wait_for_metric
    self.impalad_service.wait_for_metric_value(metric_name, expected_value, timeout)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <tests.common.impala_service.ImpaladService object at 0x7ffb24029350>
metric_name = 'impala-server.num-fragments-in-flight', expected_value = 0
timeout = 60, interval = 1

    def wait_for_metric_value(self, metric_name, expected_value, timeout=10, interval=1):
      start_time = time()
      while (time() - start_time < timeout):
        LOG.info("Getting metric: %s from %s:%s" %
            (metric_name, self.hostname, self.webserver_port))
        value = None
        try:
          value = self.get_metric_value(metric_name)
        except Exception, e:
          LOG.error(e)
    
        if value == expected_value:
          LOG.info("Metric '%s' has reach desired value: %s" % (metric_name, value))
          return value
        else:
          LOG.info("Waiting for metric value '%s'=%s. Current value: %s" %
              (metric_name, expected_value, value))
        LOG.info("Sleeping %ds before next retry." % interval)
        sleep(interval)
      assert 0, 'Metric value %s did not reach value %s in %ss' %\
>         (metric_name, expected_value, timeout)
E     AssertionError: Metric value impala-server.num-fragments-in-flight did not reach value 0 in 60s

common/impala_service.py:81: AssertionError