Getting error while running query on hive over tez. As per logs, hive is failing while copying tez jars
to a hdfs
location on start of tez session
.Below is the complete log obtained from hive log
file :
2015-06-19 01:23:52,289 INFO [HiveServer2-Background-Pool: Thread-41]: ql.Driver (SessionState.java:printInfo(852)) - Query ID = saurabh_20150619012323_f52f1d6c-2adb-4edc-8ba4-b64d7d898325
2015-06-19 01:23:52,289 INFO [HiveServer2-Background-Pool: Thread-41]: ql.Driver (SessionState.java:printInfo(852)) - Total jobs = 1
2015-06-19 01:23:52,289 INFO [HiveServer2-Background-Pool: Thread-41]: log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=TimeToSubmit start=1434657232288 end=1434657232289 duration=1 from=org.apache.hadoop.hive.ql.Driver>
2015-06-19 01:23:52,290 INFO [HiveServer2-Background-Pool: Thread-41]: log.PerfLogger (PerfLogger.java:PerfLogBegin(121)) - <PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>
2015-06-19 01:23:52,290 INFO [HiveServer2-Background-Pool: Thread-41]: log.PerfLogger (PerfLogger.java:PerfLogBegin(121)) - <PERFLOG method=task.TEZ.Stage-1 from=org.apache.hadoop.hive.ql.Driver>
2015-06-19 01:23:52,302 INFO [HiveServer2-Background-Pool: Thread-41]: ql.Driver (SessionState.java:printInfo(852)) - Launching Job 1 out of 1
2015-06-19 01:23:52,302 INFO [HiveServer2-Background-Pool: Thread-41]: ql.Driver (Driver.java:launchTask(1630)) - Starting task [Stage-1:MAPRED] in parallel
2015-06-19 01:23:52,312 INFO [Thread-21]: session.SessionState (SessionState.java:start(488)) - No Tez session required at this point. hive.execution.engine=mr.
2015-06-19 01:23:52,314 INFO [Thread-21]: tez.TezSessionPoolManager (TezSessionPoolManager.java:getSession(125)) - QueueName: null nonDefaultUser: true defaultQueuePool: null blockingQueueLength: -1
2015-06-19 01:23:52,315 INFO [Thread-21]: tez.TezSessionPoolManager (TezSessionPoolManager.java:getNewSessionState(154)) - Created a new session for queue: null session id: 85d83746-a48e-419e-a7ca-8c98faf173ea
2015-06-19 01:23:52,380 INFO [Thread-21]: Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1049)) - mapred.committer.job.setup.cleanup.needed is deprecated. Instead, use mapreduce.job.committer.setup.cleanup.needed
2015-06-19 01:23:52,412 INFO [Thread-21]: ql.Context (Context.java:getMRScratchDir(328)) - New scratch dir is hdfs://localhost:9000/tmp/hive/saurabh/e5a701ae-242d-488f-beec-cf18878becdc/hive_2015-06-19_01-23-49_794_2167174123575230985-2
2015-06-19 01:23:52,420 INFO [Thread-21]: exec.Task (TezTask.java:updateSession(233)) - Tez session hasn't been created yet. Opening session
2015-06-19 01:23:52,420 INFO [Thread-21]: tez.TezSessionState (TezSessionState.java:open(142)) - User of session id 85d83746-a48e-419e-a7ca-8c98faf173ea is saurabh
2015-06-19 01:23:52,433 INFO [Thread-21]: tez.DagUtils (DagUtils.java:localizeResource(950)) - Localizing resource because it does not exist: file:/usr/lib/tez/* to dest: hdfs://localhost:9000/tmp/hive/saurabh/_tez_session_dir/85d83746-a48e-419e-a7ca-8c98faf173ea/*
2015-06-19 01:23:52,433 INFO [Thread-21]: tez.DagUtils (DagUtils.java:localizeResource(954)) - Looks like another thread is writing the same file will wait.
2015-06-19 01:23:52,433 INFO [Thread-21]: tez.DagUtils (DagUtils.java:localizeResource(961)) - Number of wait attempts: 5. Wait interval: 5000
2015-06-19 01:24:17,449 ERROR [Thread-21]: tez.DagUtils (DagUtils.java:localizeResource(977)) - Could not find the jar that was being uploaded
2015-06-19 01:24:17,451 ERROR [Thread-21]: exec.Task (TezTask.java:execute(184)) - Failed to execute tez graph.
java.io.IOException: Previous writer likely failed to write hdfs://localhost:9000/tmp/hive/saurabh/_tez_session_dir/85d83746-a48e-419e-a7ca-8c98faf173ea/*. Failing because I am unlikely to write too.
at org.apache.hadoop.hive.ql.exec.tez.DagUtils.localizeResource(DagUtils.java:978)
at org.apache.hadoop.hive.ql.exec.tez.DagUtils.addTempResources(DagUtils.java:859)
at org.apache.hadoop.hive.ql.exec.tez.DagUtils.localizeTempFilesFromConf(DagUtils.java:802)
at org.apache.hadoop.hive.ql.exec.tez.TezSessionState.refreshLocalResourcesFromConf(TezSessionState.java:228)
at org.apache.hadoop.hive.ql.exec.tez.TezSessionState.open(TezSessionState.java:154)
at org.apache.hadoop.hive.ql.exec.tez.TezTask.updateSession(TezTask.java:234)
at org.apache.hadoop.hive.ql.exec.tez.TezTask.execute(TezTask.java:136)
at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:160)
at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:88)
at org.apache.hadoop.hive.ql.exec.TaskRunner.run(TaskRunner.java:75)
2015-06-19 01:24:18,329 ERROR [HiveServer2-Background-Pool: Thread-41]: ql.Driver (SessionState.java:printError(861)) - FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.tez.TezTask
2015-06-19 01:24:18,329 INFO [HiveServer2-Background-Pool: Thread-41]: log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=Driver.execute start=1434657232288 end=1434657258329 duration=26041 from=org.apache.hadoop.hive.ql.Driver>
2015-06-19 01:24:18,329 INFO [HiveServer2-Background-Pool: Thread-41]: log.PerfLogger (PerfLogger.java:PerfLogBegin(121)) - <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
2015-06-19 01:24:18,329 INFO [HiveServer2-Background-Pool: Thread-41]: log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=releaseLocks start=1434657258329 end=1434657258329 duration=0 from=org.apache.hadoop.hive.ql.Driver>
2015-06-19 01:24:18,333 ERROR [HiveServer2-Background-Pool: Thread-41]: operation.Operation (SQLOperation.java:run(200)) - Error running hive query:
org.apache.hive.service.cli.HiveSQLException: Error while processing statement: FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.tez.TezTask
at org.apache.hive.service.cli.operation.Operation.toSQLException(Operation.java:315)
at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:147)
at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:70)
at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:197)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1628)
at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:209)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-06-19 01:24:18,342 INFO [HiveServer2-Handler-Pool: Thread-29]: exec.ListSinkOperator (Operator.java:close(595)) - 40 finished. closing...
2015-06-19 01:24:18,343 INFO [HiveServer2-Handler-Pool: Thread-29]: exec.ListSinkOperator (Operator.java:close(613)) - 40 Close done
2015-06-19 01:24:18,393 INFO [HiveServer2-Handler-Pool: Thread-29]: log.PerfLogger (PerfLogger.java:PerfLogBegin(121)) - <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
2015-06-19 01:24:18,394 INFO [HiveServer2-Handler-Pool: Thread-29]: log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=releaseLocks start=1434657258393 end=1434657258394 duration=1 from=org.apache.hadoop.hive.ql.Driver>