Hive: Flaky test testScanTable[fileFormat=AVRO, engine=tez] org.apache.iceberg.mr.hive.TestHiveIcebergStorageHandlerWithCustomCatalog #1817
Description
The tez tests are failing from time to time with the following exception:
--------
- Test log for: Test testScanTable[fileFormat=AVRO, engine=tez](org.apache.iceberg.mr.hive.TestHiveIcebergStorageHandlerWithCustomCatalog)
--------
StdOut 2020-11-24T00:08:02,749 WARN [pool-2999-thread-5] metastore.ObjectStore (ObjectStore.java:correctAutoStartMechanism(638)) - datanucleus.autoStartMechanismMode is set to unsupported value null . Setting it to value: ignored
StdErr OKStdErr
StdErr OKStdErr
StdErr Query ID = runner_20201124000802_6680e7fc-92e5-4e5f-bdd1-e984e3c5d933StdErr
StdErr Total jobs = 1StdErr
StdErr Launching Job 1 out of 1StdErr
StdOut 2020-11-24T00:08:02,901 INFO [7b4a309c-08d4-4f1f-a02b-2652ad201223 Test worker] exec.Task (TezTask.java:execute(190)) - Subscribed to counters: [] for queryId: runner_20201124000802_6680e7fc-92e5-4e5f-bdd1-e984e3c5d933
StdOut 2020-11-24T00:08:02,902 INFO [7b4a309c-08d4-4f1f-a02b-2652ad201223 Test worker] exec.Task (TezTask.java:ensureSessionHasResources(367)) - Tez session hasn't been created yet. Opening session
StdOut 2020-11-24T00:08:03,067 ERROR [ServiceThread:DAGClientRPCServer] client.DAGClientServer (DAGClientServer.java:serviceStart(99)) - Failed to start DAGClientServer:
StdOut org.apache.hadoop.metrics2.MetricsException: Metrics source RpcActivityForPort33797 already exists!
StdOut at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.newSourceName(DefaultMetricsSystem.java:152) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.sourceName(DefaultMetricsSystem.java:125) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.register(MetricsSystemImpl.java:229) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.metrics.RpcMetrics.create(RpcMetrics.java:87) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.Server.<init>(Server.java:2810) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.RPC$Server.<init>(RPC.java:960) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.ProtobufRpcEngine$Server.<init>(ProtobufRpcEngine.java:421) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.ProtobufRpcEngine.getServer(ProtobufRpcEngine.java:342) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.RPC$Builder.build(RPC.java:802) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.tez.dag.api.client.DAGClientServer.createServer(DAGClientServer.java:134) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.dag.api.client.DAGClientServer.serviceStart(DAGClientServer.java:82) [tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.hadoop.service.AbstractService.start(AbstractService.java:194) [hadoop-common-3.1.0.jar:?]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceWithDependency.start(DAGAppMaster.java:1865) [tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceThread.run(DAGAppMaster.java:1886) [tez-dag-0.9.1.jar:0.9.1]
StdOut 2020-11-24T00:08:03,078 ERROR [DAGAppMaster Thread] client.LocalClient (LocalClient.java:run(331)) - Error starting DAGAppMaster
StdOut org.apache.tez.dag.api.TezUncheckedException: org.apache.hadoop.metrics2.MetricsException: Metrics source RpcActivityForPort33797 already exists!
StdOut at org.apache.tez.dag.api.client.DAGClientServer.serviceStart(DAGClientServer.java:100) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.hadoop.service.AbstractService.start(AbstractService.java:194) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceWithDependency.start(DAGAppMaster.java:1865) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceThread.run(DAGAppMaster.java:1886) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut Caused by: org.apache.hadoop.metrics2.MetricsException: Metrics source RpcActivityForPort33797 already exists!
StdOut at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.newSourceName(DefaultMetricsSystem.java:152) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.sourceName(DefaultMetricsSystem.java:125) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.register(MetricsSystemImpl.java:229) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.metrics.RpcMetrics.create(RpcMetrics.java:87) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.Server.<init>(Server.java:2810) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.RPC$Server.<init>(RPC.java:960) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.ProtobufRpcEngine$Server.<init>(ProtobufRpcEngine.java:421) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.ProtobufRpcEngine.getServer(ProtobufRpcEngine.java:342) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.RPC$Builder.build(RPC.java:802) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.tez.dag.api.client.DAGClientServer.createServer(DAGClientServer.java:134) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.dag.api.client.DAGClientServer.serviceStart(DAGClientServer.java:82) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut ... 3 more
StdOut 2020-11-24T00:08:03,114 ERROR [7b4a309c-08d4-4f1f-a02b-2652ad201223 Test worker] exec.Task (TezTask.java:execute(284)) - Failed to execute tez graph.
StdOut java.io.IOException: org.apache.tez.dag.api.TezUncheckedException: org.apache.hadoop.metrics2.MetricsException: Metrics source RpcActivityForPort33797 already exists!
StdOut at org.apache.tez.client.LocalClient.startDAGAppMaster(LocalClient.java:276) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.client.LocalClient.submitApplication(LocalClient.java:136) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.client.TezClient.start(TezClient.java:440) ~[tez-api-0.9.1.jar:0.9.1]
StdOut at org.apache.hadoop.hive.ql.exec.tez.TezSessionState.startSessionAndContainers(TezSessionState.java:433) ~[hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.exec.tez.TezSessionState.openInternal(TezSessionState.java:368) ~[hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.exec.tez.TezSessionPoolSession.openInternal(TezSessionPoolSession.java:124) ~[hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.exec.tez.TezSessionState.open(TezSessionState.java:245) ~[hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.exec.tez.TezTask.ensureSessionHasResources(TezTask.java:368) ~[hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.exec.tez.TezTask.execute(TezTask.java:195) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:205) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:97) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:2664) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:2335) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:2011) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1709) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1703) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hadoop.hive.ql.reexec.ReExecDriver.run(ReExecDriver.java:157) [hive-exec-3.1.2-core.jar:3.1.2]
StdOut at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:224) [hive-service-3.1.2.jar:3.1.2]
StdOut at org.apache.hive.service.cli.operation.SQLOperation.runInternal(SQLOperation.java:263) [hive-service-3.1.2.jar:3.1.2]
StdOut at org.apache.hive.service.cli.operation.Operation.run(Operation.java:247) [hive-service-3.1.2.jar:3.1.2]
StdOut at org.apache.hive.service.cli.session.HiveSessionImpl.executeStatementInternal(HiveSessionImpl.java:541) [hive-service-3.1.2.jar:3.1.2]
StdOut at org.apache.hive.service.cli.session.HiveSessionImpl.executeStatement(HiveSessionImpl.java:510) [hive-service-3.1.2.jar:3.1.2]
StdOut at org.apache.hive.service.cli.CLIService.executeStatement(CLIService.java:267) [hive-service-3.1.2.jar:3.1.2]
StdOut at org.apache.iceberg.mr.hive.TestHiveShell.executeStatement(TestHiveShell.java:129) [test/:?]
StdOut at org.apache.iceberg.mr.hive.HiveIcebergStorageHandlerBaseTest.testScanTable(HiveIcebergStorageHandlerBaseTest.java:203) [test/:?]
StdOut at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_275]
StdOut at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_275]
StdOut at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_275]
StdOut at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_275]
StdOut at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) [junit-4.12.jar:4.12]
StdOut at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) [junit-4.12.jar:4.12]
StdOut at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) [junit-4.12.jar:4.12]
StdOut at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) [junit-4.12.jar:4.12]
StdOut at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) [junit-4.12.jar:4.12]
StdOut at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48) [junit-4.12.jar:4.12]
StdOut at org.junit.rules.RunRules.evaluate(RunRules.java:20) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner.run(ParentRunner.java:363) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.Suite.runChild(Suite.java:128) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.Suite.runChild(Suite.java:27) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) [junit-4.12.jar:4.12]
StdOut at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) [junit-4.12.jar:4.12]
StdOut at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) [junit-4.12.jar:4.12]
StdOut at org.junit.runners.ParentRunner.run(ParentRunner.java:363) [junit-4.12.jar:4.12]
StdOut at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:110) [gradle-testing-jvm-5.4.1.jar:5.4.1]
StdOut at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58) [gradle-testing-jvm-5.4.1.jar:5.4.1]
StdOut at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38) [gradle-testing-jvm-5.4.1.jar:5.4.1]
StdOut at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:62) [gradle-testing-jvm-5.4.1.jar:5.4.1]
StdOut at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51) [gradle-testing-base-5.4.1.jar:5.4.1]
StdOut at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_275]
StdOut at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_275]
StdOut at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_275]
StdOut at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_275]
StdOut at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at com.sun.proxy.$Proxy2.processTestClass(Unknown Source) [?:?]
StdOut at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:118) [gradle-testing-base-5.4.1.jar:5.4.1]
StdOut at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_275]
StdOut at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_275]
StdOut at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_275]
StdOut at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_275]
StdOut at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:175) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:157) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404) [gradle-messaging-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63) [gradle-base-services-5.4.1.jar:5.4.1]
StdOut at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46) [gradle-base-services-5.4.1.jar:5.4.1]
StdOut at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_275]
StdOut at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_275]
StdOut at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55) [gradle-base-services-5.4.1.jar:5.4.1]
StdOut at java.lang.Thread.run(Thread.java:748) [?:1.8.0_275]
StdOut Caused by: org.apache.tez.dag.api.TezUncheckedException: org.apache.hadoop.metrics2.MetricsException: Metrics source RpcActivityForPort33797 already exists!
StdOut at org.apache.tez.dag.api.client.DAGClientServer.serviceStart(DAGClientServer.java:100) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.hadoop.service.AbstractService.start(AbstractService.java:194) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceWithDependency.start(DAGAppMaster.java:1865) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceThread.run(DAGAppMaster.java:1886) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut Caused by: org.apache.hadoop.metrics2.MetricsException: Metrics source RpcActivityForPort33797 already exists!
StdOut at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.newSourceName(DefaultMetricsSystem.java:152) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.sourceName(DefaultMetricsSystem.java:125) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.register(MetricsSystemImpl.java:229) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.metrics.RpcMetrics.create(RpcMetrics.java:87) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.Server.<init>(Server.java:2810) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.RPC$Server.<init>(RPC.java:960) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.ProtobufRpcEngine$Server.<init>(ProtobufRpcEngine.java:421) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.ProtobufRpcEngine.getServer(ProtobufRpcEngine.java:342) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.hadoop.ipc.RPC$Builder.build(RPC.java:802) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.tez.dag.api.client.DAGClientServer.createServer(DAGClientServer.java:134) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.dag.api.client.DAGClientServer.serviceStart(DAGClientServer.java:82) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.hadoop.service.AbstractService.start(AbstractService.java:194) ~[hadoop-common-3.1.0.jar:?]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceWithDependency.start(DAGAppMaster.java:1865) ~[tez-dag-0.9.1.jar:0.9.1]
StdOut at org.apache.tez.dag.app.DAGAppMaster$ServiceThread.run(DAGAppMaster.java:1886) ~[tez-dag-0.9.1.jar:0.9.1]
StdErr FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.tez.TezTaskStdErr
StdOut 2020-11-24T00:08:03,119 ERROR [7b4a309c-08d4-4f1f-a02b-2652ad201223 Test worker] ql.Driver (SessionState.java:printError(1250)) - FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.tez.TezTask