[IMPALA-7593] test_automatic_invalidation failing in S3

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: Impala 3.1.0
• Fix Version/s: Impala 3.1.0
• Component/s: Infrastructure
• Labels: broken-build
• Epic Color: ghx-label-3
• Assignee: Tianyi Wang
• Reporter: Thomas Tauber-Marshall
• Created: 19/Sep/18 17:34
• Updated: 27/Sep/18 02:14
• Resolved: 27/Sep/18 02:14

Description

Note that the build has the fix for IMPALA-7580

4:59:01 _______________ TestAutomaticCatalogInvalidation.test_v1_catalog _______________
04:59:01 custom_cluster/test_automatic_invalidation.py:63: in test_v1_catalog
04:59:01     self._run_test(cursor)
04:59:01 custom_cluster/test_automatic_invalidation.py:58: in _run_test
04:59:01     assert time.time() < timeout
04:59:01 E   assert 1537355634.805718 < 1537355634.394429
04:59:01 E    +  where 1537355634.805718 = <built-in function time>()
04:59:01 E    +    where <built-in function time> = time.time
04:59:01 ---------------------------- Captured stderr setup -----------------------------
04:59:01 -- 2018-09-19 04:13:22,796 INFO     MainThread: Starting cluster with command: /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/bin/start-impala-cluster.py --cluster_size=3 --num_coordinators=3 --log_dir=/data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests --log_level=1 '--impalad_args="--invalidate_tables_timeout_s=20" ' '--state_store_args="--statestore_update_frequency_ms=50     --statestore_priority_update_frequency_ms=50     --statestore_heartbeat_frequency_ms=50" ' '--catalogd_args="--invalidate_tables_timeout_s=20" '
04:59:01 04:13:23 MainThread: Starting State Store logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/statestored.INFO
04:59:01 04:13:23 MainThread: Starting Catalog Service logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/catalogd.INFO
04:59:01 04:13:24 MainThread: Starting Impala Daemon logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/impalad.INFO
04:59:01 04:13:25 MainThread: Starting Impala Daemon logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/impalad_node1.INFO
04:59:01 04:13:26 MainThread: Starting Impala Daemon logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/impalad_node2.INFO
04:59:01 04:13:29 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
04:59:01 04:13:29 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 04:13:29 MainThread: Waiting for num_known_live_backends=3. Current value: 0
04:59:01 04:13:30 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 04:13:30 MainThread: Waiting for num_known_live_backends=3. Current value: 1
04:59:01 04:13:31 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 04:13:31 MainThread: Waiting for num_known_live_backends=3. Current value: 2
04:59:01 04:13:32 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 04:13:32 MainThread: num_known_live_backends has reached value: 3
04:59:01 04:13:32 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25001
04:59:01 04:13:32 MainThread: num_known_live_backends has reached value: 3
04:59:01 04:13:32 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25002
04:59:01 04:13:32 MainThread: num_known_live_backends has reached value: 3
04:59:01 04:13:32 MainThread: Impala Cluster Running with 3 nodes (3 coordinators, 3 executors).
04:59:01 -- 2018-09-19 04:13:33,034 INFO     MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
04:59:01 -- 2018-09-19 04:13:33,034 INFO     MainThread: Getting metric: statestore.live-backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25010
04:59:01 -- 2018-09-19 04:13:33,036 INFO     MainThread: Metric 'statestore.live-backends' has reached desired value: 4
04:59:01 -- 2018-09-19 04:13:33,036 INFO     MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 -- 2018-09-19 04:13:33,037 INFO     MainThread: num_known_live_backends has reached value: 3
04:59:01 -- 2018-09-19 04:13:33,037 INFO     MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25001
04:59:01 -- 2018-09-19 04:13:33,038 INFO     MainThread: num_known_live_backends has reached value: 3
04:59:01 -- 2018-09-19 04:13:33,038 INFO     MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25002
04:59:01 -- 2018-09-19 04:13:33,038 INFO     MainThread: num_known_live_backends has reached value: 3
04:59:01 -- connecting to: localhost:21000
04:59:01 _____________ TestAutomaticCatalogInvalidation.test_local_catalog ______________
04:59:01 custom_cluster/test_automatic_invalidation.py:70: in test_local_catalog
04:59:01     self._run_test(cursor)
04:59:01 custom_cluster/test_automatic_invalidation.py:58: in _run_test
04:59:01     assert time.time() < timeout
04:59:01 E   assert 1537355665.741225 < 1537355665.319975
04:59:01 E    +  where 1537355665.741225 = <built-in function time>()
04:59:01 E    +    where <built-in function time> = time.time
04:59:01 ---------------------------- Captured stderr setup -----------------------------
04:59:01 -- 2018-09-19 04:13:54,825 INFO     MainThread: Starting cluster with command: /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/bin/start-impala-cluster.py --cluster_size=3 --num_coordinators=3 --log_dir=/data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests --log_level=1 '--impalad_args="--invalidate_tables_timeout_s=20 --use_local_catalog" ' '--state_store_args="--statestore_update_frequency_ms=50     --statestore_priority_update_frequency_ms=50     --statestore_heartbeat_frequency_ms=50" ' '--catalogd_args="--invalidate_tables_timeout_s=20 --catalog_topic_mode=minimal" '
04:59:01 04:13:55 MainThread: Starting State Store logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/statestored.INFO
04:59:01 04:13:55 MainThread: Starting Catalog Service logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/catalogd.INFO
04:59:01 04:13:56 MainThread: Starting Impala Daemon logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/impalad.INFO
04:59:01 04:13:57 MainThread: Starting Impala Daemon logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/impalad_node1.INFO
04:59:01 04:13:58 MainThread: Starting Impala Daemon logging to /data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/logs/custom_cluster_tests/impalad_node2.INFO
04:59:01 04:14:01 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
04:59:01 04:14:01 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 04:14:01 MainThread: Waiting for num_known_live_backends=3. Current value: 1
04:59:01 04:14:02 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 04:14:02 MainThread: Waiting for num_known_live_backends=3. Current value: 2
04:59:01 04:14:03 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 04:14:03 MainThread: num_known_live_backends has reached value: 3
04:59:01 04:14:03 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25001
04:59:01 04:14:03 MainThread: num_known_live_backends has reached value: 3
04:59:01 04:14:03 MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25002
04:59:01 04:14:03 MainThread: num_known_live_backends has reached value: 3
04:59:01 04:14:03 MainThread: Impala Cluster Running with 3 nodes (3 coordinators, 3 executors).
04:59:01 -- 2018-09-19 04:14:03,882 INFO     MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
04:59:01 -- 2018-09-19 04:14:03,882 INFO     MainThread: Getting metric: statestore.live-backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25010
04:59:01 -- 2018-09-19 04:14:03,884 INFO     MainThread: Metric 'statestore.live-backends' has reached desired value: 4
04:59:01 -- 2018-09-19 04:14:03,884 INFO     MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25000
04:59:01 -- 2018-09-19 04:14:03,885 INFO     MainThread: num_known_live_backends has reached value: 3
04:59:01 -- 2018-09-19 04:14:03,885 INFO     MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25001
04:59:01 -- 2018-09-19 04:14:03,885 INFO     MainThread: num_known_live_backends has reached value: 3
04:59:01 -- 2018-09-19 04:14:03,886 INFO     MainThread: Getting num_known_live_backends from impala-ec2-centos74-r4-4xlarge-ondemand-1860.vpc.cloudera.com:25002
04:59:01 -- 2018-09-19 04:14:03,886 INFO     MainThread: num_known_live_backends has reached value: 3
04:59:01 -- connecting to: localhost:21000
04:59:01 -- 2018-09-19 04:14:03,887 ERROR    MainThread: Failed to open transport (tries_left=3)
04:59:01 Traceback (most recent call last):
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/infra/python/env/lib/python2.7/site-packages/impala/hiveserver2.py", line 940, in _execute
04:59:01     return func(request)
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/infra/python/env/lib/python2.7/site-packages/impala/_thrift_gen/TCLIService/TCLIService.py", line 175, in OpenSession
04:59:01     return self.recv_OpenSession()
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/repos/Impala/infra/python/env/lib/python2.7/site-packages/impala/_thrift_gen/TCLIService/TCLIService.py", line 186, in recv_OpenSession
04:59:01     (fname, mtype, rseqid) = self._iprot.readMessageBegin()
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/Impala-Toolchain/thrift-0.9.3-p4/python/lib64/python2.7/site-packages/thrift/protocol/TBinaryProtocol.py", line 126, in readMessageBegin
04:59:01     sz = self.readI32()
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/Impala-Toolchain/thrift-0.9.3-p4/python/lib64/python2.7/site-packages/thrift/protocol/TBinaryProtocol.py", line 206, in readI32
04:59:01     buff = self.trans.readAll(4)
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/Impala-Toolchain/thrift-0.9.3-p4/python/lib64/python2.7/site-packages/thrift/transport/TTransport.py", line 58, in readAll
04:59:01     chunk = self.read(sz - have)
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/Impala-Toolchain/thrift-0.9.3-p4/python/lib64/python2.7/site-packages/thrift/transport/TTransport.py", line 159, in read
04:59:01     self.__rbuf = StringIO(self.__trans.read(max(sz, self.__rbuf_size)))
04:59:01   File "/data/jenkins/workspace/impala-asf-master-core-asan/Impala-Toolchain/thrift-0.9.3-p4/python/lib64/python2.7/site-packages/thrift/transport/TSocket.py", line 120, in read
04:59:01     message='TSocket read 0 bytes')
04:59:01 TTransportException: TSocket read 0 bytes

Issue Links

• relates to: IMPALA-7594 TestAutomaticCatalogInvalidation.test_local_catalog and test_v1_catalog still hitting timeout