Uploaded image for project: 'Hive'
  1. Hive
  2. HIVE-13017

Child process of HiveServer2 fails to get delegation token from non default FileSystem

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 1.2.1
    • 2.1.0
    • Authentication
    • None
    • Secure

    Description

      The following query fails, when Azure Filesystem is used as default file system, and HDFS is used for intermediate data.

      >>>  create temporary table s10k stored as orc as select * from studenttab10k;
      >>>  create temporary table v10k as select * from votertab10k;
      >>>  select registration 
      from s10k s join v10k v 
      on (s.name = v.name) join studentparttab30k p 
      on (p.name = v.name) 
      where s.age < 25 and v.age < 25 and p.age < 25;
      ERROR : Execution failed with exit status: 2
      ERROR : Obtaining error information
      ERROR : 
      Task failed!
      Task ID:
        Stage-5
      
      Logs:
      
      ERROR : /var/log/hive/hiveServer2.log
      Error: Error while processing statement: FAILED: Execution Error, return code 2 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask (state=08S01,code=2)
      Aborting command set because "force" is false and command failed: "select registration 
      from s10k s join v10k v 
      on (s.name = v.name) join studentparttab30k p 
      on (p.name = v.name) 
      where s.age < 25 and v.age < 25 and p.age < 25;"
      Closing: 0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181/;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;principal=hive/_HOST@HDINSIGHT.NET;transportMode=http;httpPath=cliservice
      hiveServer2.log shows:
      2016-02-02 18:04:34,182 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=Driver.run from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,199 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=TimeToSubmit from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,212 INFO  [HiveServer2-HttpHandler-Pool: Thread-55]: thrift.ThriftHttpServlet (ThriftHttpServlet.java:doPost(127)) - Could not validate cookie sent, will try to generate a new cookie
      2016-02-02 18:04:34,213 INFO  [HiveServer2-Background-Pool: Thread-517]: ql.Driver (Driver.java:checkConcurrency(168)) - Concurrency mode is disabled, not creating a lock manager
      2016-02-02 18:04:34,219 INFO  [HiveServer2-HttpHandler-Pool: Thread-55]: thrift.ThriftHttpServlet (ThriftHttpServlet.java:doKerberosAuth(352)) - Failed to authenticate with http/_HOST kerberos principal, trying with hive/_HOST kerberos principal
      2016-02-02 18:04:34,219 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=Driver.execute from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,225 INFO  [HiveServer2-Background-Pool: Thread-517]: ql.Driver (Driver.java:execute(1390)) - Setting caller context to query id hive_20160202180429_7ffff6ab-64d6-4c89-88b0-6355cc5acbd0
      2016-02-02 18:04:34,226 INFO  [HiveServer2-Background-Pool: Thread-517]: ql.Driver (Driver.java:execute(1393)) - Starting command(queryId=hive_20160202180429_7ffff6ab-64d6-4c89-88b0-6355cc5acbd0): select registration
      from s10k s join v10k v
      on (s.name = v.name) join studentparttab30k p
      on (p.name = v.name)
      where s.age < 25 and v.age < 25 and p.age < 25
      2016-02-02 18:04:34,228 INFO  [HiveServer2-Background-Pool: Thread-517]: hooks.ATSHook (ATSHook.java:<init>(90)) - Created ATS Hook
      2016-02-02 18:04:34,229 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=PreHook.org.apache.hadoop.hive.ql.hooks.ATSHook from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,237 INFO  [HiveServer2-HttpHandler-Pool: Thread-55]: thrift.ThriftHttpServlet (ThriftHttpServlet.java:doPost(169)) - Cookie added for clientUserName hrt_qa
      2016-02-02 18:04:34,238 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogEnd(162)) - </PERFLOG method=PreHook.org.apache.hadoop.hive.ql.hooks.ATSHook start=1454436274229 end=1454436274238 duration=9 from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,239 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=PreHook.org.apache.hadoop.hive.ql.security.authorization.plugin.DisallowTransformHook from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,240 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogEnd(162)) - </PERFLOG method=PreHook.org.apache.hadoop.hive.ql.security.authorization.plugin.DisallowTransformHook start=1454436274239 end=1454436274240 duration=1 from=org.apache.hadoop.hive.ql.Driver>
      Query ID = hive_20160202180429_7ffff6ab-64d6-4c89-88b0-6355cc5acbd0
      2016-02-02 18:04:34,242 INFO  [HiveServer2-Background-Pool: Thread-517]: ql.Driver (SessionState.java:printInfo(923)) - Query ID = hive_20160202180429_7ffff6ab-64d6-4c89-88b0-6355cc5acbd0
      Total jobs = 1
      2016-02-02 18:04:34,243 INFO  [HiveServer2-Background-Pool: Thread-517]: ql.Driver (SessionState.java:printInfo(923)) - Total jobs = 1
      2016-02-02 18:04:34,245 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogEnd(162)) - </PERFLOG method=TimeToSubmit start=1454436274199 end=1454436274245 duration=46 from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,246 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,247 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=task.MAPREDLOCAL.Stage-5 from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:34,258 INFO  [HiveServer2-Background-Pool: Thread-517]: ql.Driver (Driver.java:launchTask(1718)) - Starting task [Stage-5:MAPREDLOCAL] in serial mode
      2016-02-02 18:04:34,280 INFO  [HiveServer2-Background-Pool: Thread-517]: mr.MapredLocalTask (MapredLocalTask.java:executeInChildVM(158)) - Generating plan file file:/tmp/hive/916e3dbb-a10d-4888-a063-52fb058ea421/hive_2016-02-02_18-04-29_153_625340340820843828-4/-local-10006/plan.xml
      2016-02-02 18:04:34,288 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=serializePlan from=org.apache.hadoop.hive.ql.exec.Utilities>
      2016-02-02 18:04:34,289 INFO  [HiveServer2-Background-Pool: Thread-517]: exec.Utilities (Utilities.java:serializePlan(1028)) - Serializing MapredLocalWork via kryo
      2016-02-02 18:04:34,290 INFO  [ATS Logger 0]: hooks.ATSHook (ATSHook.java:createPreHookEvent(158)) - Received pre-hook notification for :hive_20160202180429_7ffff6ab-64d6-4c89-88b0-6355cc5acbd0
      2016-02-02 18:04:34,358 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogEnd(162)) - </PERFLOG method=serializePlan start=1454436274288 end=1454436274358 duration=70 from=org.apache.hadoop.hive.ql.exec.Utilities>
      2016-02-02 18:04:34,737 INFO  [HiveServer2-Background-Pool: Thread-517]: mr.MapredLocalTask (MapredLocalTask.java:executeInChildVM(287)) - Executing: /usr/hdp/2.4.1.0-170/hadoop/bin/hadoop jar /usr/hdp/2.4.1.0-170/hive/lib/hive-common-1.2.1000.2.4.1.0-170.jar org.apache.hadoop.hive.ql.exec.mr.ExecDriver -localtask -plan file:/tmp/hive/916e3dbb-a10d-4888-a063-52fb058ea421/hive_2016-02-02_18-04-29_153_625340340820843828-4/-local-10006/plan.xml   -jobconffile file:/tmp/hive/916e3dbb-a10d-4888-a063-52fb058ea421/hive_2016-02-02_18-04-29_153_625340340820843828-4/-local-10007/jobconf.xml
      WARNING: Use "yarn jar" to launch YARN applications.
      2016-02-02 18:04:37,450 INFO  [org.apache.ranger.audit.queue.AuditBatchQueue0]: provider.BaseAuditHandler (BaseAuditHandler.java:logStatus(312)) - Audit Status Log: name=hiveServer2.async.summary.batch.solr, interval=01:21.012 minutes, events=2, succcessCount=2, totalEvents=4, totalSuccessCount=4
      Execution log at: /tmp/hive/hive_20160202180429_7ffff6ab-64d6-4c89-88b0-6355cc5acbd0.log
      2016-02-02 18:04:39,248 INFO  [HiveServer2-HttpHandler-Pool: Thread-55]: thrift.ThriftHttpServlet (ThriftHttpServlet.java:doPost(127)) - Could not validate cookie sent, will try to generate a new cookie
      2016-02-02 18:04:39,254 INFO  [HiveServer2-HttpHandler-Pool: Thread-55]: thrift.ThriftHttpServlet (ThriftHttpServlet.java:doKerberosAuth(352)) - Failed to authenticate with http/_HOST kerberos principal, trying with hive/_HOST kerberos principal
      2016-02-02 18:04:39,261 INFO  [HiveServer2-HttpHandler-Pool: Thread-55]: thrift.ThriftHttpServlet (ThriftHttpServlet.java:doPost(169)) - Cookie added for clientUserName hrt_qa
      2016-02-02 18:04:40     Starting to launch local task to process map join;      maximum memory = 477102080
      Execution failed with exit status: 2
      2016-02-02 18:04:43,728 ERROR [HiveServer2-Background-Pool: Thread-517]: exec.Task (SessionState.java:printError(932)) - Execution failed with exit status: 2
      Obtaining error information
      2016-02-02 18:04:43,730 ERROR [HiveServer2-Background-Pool: Thread-517]: exec.Task (SessionState.java:printError(932)) - Obtaining error information
      
      Task failed!
      Task ID:
        Stage-5
      
      Logs:
      
      2016-02-02 18:04:43,730 ERROR [HiveServer2-Background-Pool: Thread-517]: exec.Task (SessionState.java:printError(932)) -
      Task failed!
      Task ID:
        Stage-5
      
      Logs:
      
      /var/log/hive/hiveServer2.log
      2016-02-02 18:04:43,732 ERROR [HiveServer2-Background-Pool: Thread-517]: exec.Task (SessionState.java:printError(932)) - /var/log/hive/hiveServer2.log
      2016-02-02 18:04:43,732 ERROR [HiveServer2-Background-Pool: Thread-517]: mr.MapredLocalTask (MapredLocalTask.java:executeInChildVM(307)) - Execution failed with exit status: 2
      2016-02-02 18:04:43,733 INFO  [HiveServer2-Background-Pool: Thread-517]: hooks.ATSHook (ATSHook.java:<init>(90)) - Created ATS Hook
      2016-02-02 18:04:43,734 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=FailureHook.org.apache.hadoop.hive.ql.hooks.ATSHook from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:43,736 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogEnd(162)) - </PERFLOG method=FailureHook.org.apache.hadoop.hive.ql.hooks.ATSHook start=1454436283734 end=1454436283736 duration=2 from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:43,736 INFO  [ATS Logger 0]: hooks.ATSHook (ATSHook.java:createPostHookEvent(193)) - Received post-hook notification for :hive_20160202180429_7ffff6ab-64d6-4c89-88b0-6355cc5acbd0
      FAILED: Execution Error, return code 2 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask
      2016-02-02 18:04:43,757 ERROR [HiveServer2-Background-Pool: Thread-517]: ql.Driver (SessionState.java:printError(932)) - FAILED: Execution Error, return code 2 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask
      2016-02-02 18:04:43,758 INFO  [HiveServer2-Background-Pool: Thread-517]: ql.Driver (Driver.java:execute(1621)) - Resetting the caller context to HIVE_SSN_ID:916e3dbb-a10d-4888-a063-52fb058ea421
      2016-02-02 18:04:43,759 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogEnd(162)) - </PERFLOG method=Driver.execute start=1454436274219 end=1454436283759 duration=9540 from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:43,760 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogBegin(135)) - <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:43,761 INFO  [HiveServer2-Background-Pool: Thread-517]: log.PerfLogger (PerfLogger.java:PerfLogEnd(162)) - </PERFLOG method=releaseLocks start=1454436283760 end=1454436283761 duration=1 from=org.apache.hadoop.hive.ql.Driver>
      2016-02-02 18:04:43,766 ERROR [HiveServer2-Background-Pool: Thread-517]: operation.Operation (SQLOperation.java:run(209)) - Error running hive query:
      org.apache.hive.service.cli.HiveSQLException: Error while processing statement: FAILED: Execution Error, return code 2 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask
              at org.apache.hive.service.cli.operation.Operation.toSQLException(Operation.java:315)
              at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:156)
              at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:71)
              at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:206)
              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:1657)
              at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:218)
              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)
      hive Configs can be viewed from http://qelog.hortonworks.com/log/hs21-hbs24-1454382123/artifacts/tmpModifyConfDir_1454394513592/
      Attachments
      Drop files to attach, or browse.
      Add LinkIssue Links
      relates to
      Bug - A problem which impairs or prevents the functions of the product. HIVE-739 webhcat tests failing in HDInsight secure cluster throwing NullPointerException	 Blocker - Blocks development and/or testing work, production could not run. RESOLVED
      Activity
      All
      Comments
      Work Log
      History
      Activity
      Ascending order - Click to sort in descending order
      Permalink Edit Delete 
      tsaito Takahiko Saito added a comment - 3 days ago
      The test passes via hive CLI and explain shows:
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> explain select registration
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> from s10k s join v10k v
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> on (s.name = v.name) join studentparttab30k p
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> on (p.name = v.name)
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> where s.age < 25 and v.age < 25 and p.age < 25;
      +--------------------------------------------------------------------------------------------------------------+--+
      |                                                   Explain                                                    |
      +--------------------------------------------------------------------------------------------------------------+--+
      | STAGE DEPENDENCIES:                                                                                          |
      |   Stage-5 is a root stage                                                                                    |
      |   Stage-4 depends on stages: Stage-5                                                                         |
      |   Stage-0 depends on stages: Stage-4                                                                         |
      |                                                                                                              |
      | STAGE PLANS:                                                                                                 |
      |   Stage: Stage-5                                                                                             |
      |     Map Reduce Local Work                                                                                    |
      |       Alias -> Map Local Tables:                                                                             |
      |         s                                                                                                    |
      |           Fetch Operator                                                                                     |
      |             limit: -1                                                                                        |
      |         v                                                                                                    |
      |           Fetch Operator                                                                                     |
      |             limit: -1                                                                                        |
      |       Alias -> Map Local Operator Tree:                                                                      |
      |         s                                                                                                    |
      |           TableScan                                                                                          |
      |             alias: s                                                                                         |
      |             filterExpr: (name is not null and (age < 25)) (type: boolean)                                    |
      |             Statistics: Num rows: 459 Data size: 47777 Basic stats: COMPLETE Column stats: NONE              |
      |             Filter Operator                                                                                  |
      |               predicate: (name is not null and (age < 25)) (type: boolean)                                   |
      |               Statistics: Num rows: 76 Data size: 7910 Basic stats: COMPLETE Column stats: NONE              |
      |               HashTable Sink Operator                                                                        |
      |                 keys:                                                                                        |
      |                   0 name (type: string)                                                                      |
      |                   1 name (type: string)                                                                      |
      |                   2 name (type: string)                                                                      |
      |         v                                                                                                    |
      |           TableScan                                                                                          |
      |             alias: v                                                                                         |
      |             filterExpr: (name is not null and (age < 25)) (type: boolean)                                    |
      |             Statistics: Num rows: 1653 Data size: 337233 Basic stats: COMPLETE Column stats: NONE            |
      |             Filter Operator                                                                                  |
      |               predicate: (name is not null and (age < 25)) (type: boolean)                                   |
      |               Statistics: Num rows: 275 Data size: 56103 Basic stats: COMPLETE Column stats: NONE            |
      |               HashTable Sink Operator                                                                        |
      |                 keys:                                                                                        |
      |                   0 name (type: string)                                                                      |
      |                   1 name (type: string)                                                                      |
      |                   2 name (type: string)                                                                      |
      |                                                                                                              |
      |   Stage: Stage-4                                                                                             |
      |     Map Reduce                                                                                               |
      |       Map Operator Tree:                                                                                     |
      |           TableScan                                                                                          |
      |             alias: p                                                                                         |
      |             filterExpr: (name is not null and (age < 25)) (type: boolean)                                    |
      |             Statistics: Num rows: 30000 Data size: 627520 Basic stats: COMPLETE Column stats: COMPLETE       |
      |             Filter Operator                                                                                  |
      |               predicate: (name is not null and (age < 25)) (type: boolean)                                   |
      |               Statistics: Num rows: 10000 Data size: 1010000 Basic stats: COMPLETE Column stats: COMPLETE    |
      |               Map Join Operator                                                                              |
      |                 condition map:                                                                               |
      |                      Inner Join 0 to 1                                                                       |
      |                      Inner Join 1 to 2                                                                       |
      |                 keys:                                                                                        |
      |                   0 name (type: string)                                                                      |
      |                   1 name (type: string)                                                                      |
      |                   2 name (type: string)                                                                      |
      |                 outputColumnNames: _col8                                                                     |
      |                 Statistics: Num rows: 22000 Data size: 2222000 Basic stats: COMPLETE Column stats: NONE      |
      |                 Select Operator                                                                              |
      |                   expressions: _col8 (type: string)                                                          |
      |                   outputColumnNames: _col0                                                                   |
      |                   Statistics: Num rows: 22000 Data size: 2222000 Basic stats: COMPLETE Column stats: NONE    |
      |                   File Output Operator                                                                       |
      |                     compressed: false                                                                        |
      |                     Statistics: Num rows: 22000 Data size: 2222000 Basic stats: COMPLETE Column stats: NONE  |
      |                     table:                                                                                   |
      |                         input format: org.apache.hadoop.mapred.TextInputFormat                               |
      |                         output format: org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat            |
      |                         serde: org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe                            |
      |       Local Work:                                                                                            |
      |         Map Reduce Local Work                                                                                |
      |                                                                                                              |
      |   Stage: Stage-0                                                                                             |
      |     Fetch Operator                                                                                           |
      |       limit: -1                                                                                              |
      |       Processor Tree:                                                                                        |
      |         ListSink                                                                                             |
      |                                                                                                              |
      +--------------------------------------------------------------------------------------------------------------+--+
      83 rows selected (2.473 seconds)
      Permalink Edit Delete 
      tsaito Takahiko Saito added a comment - 3 days ago
      emptablemisc_8 also fails with the same error:
      >>>  create temporary table temp1 as select * from votertab10k;
      >>>  select * 
      from studenttab10k s 
      where s.name not in 
      (select name from temp1);
      INFO  : Number of reduce tasks determined at compile time: 1
      INFO  : In order to change the average load for a reducer (in bytes):
      INFO  :   set hive.exec.reducers.bytes.per.reducer=<number>
      INFO  : In order to limit the maximum number of reducers:
      INFO  :   set hive.exec.reducers.max=<number>
      INFO  : In order to set a constant number of reducers:
      INFO  :   set mapreduce.job.reduces=<number>
      INFO  : number of splits:1
      INFO  : Submitting tokens for job: job_1454394534358_0164
      INFO  : Kind: HDFS_DELEGATION_TOKEN, Service: 10.0.0.36:8020, Ident: (HDFS_DELEGATION_TOKEN token 246 for hrt_qa)
      INFO  : The url to track the job: http://hn0-hs21-h.hdinsight.net:8088/proxy/application_1454394534358_0164/
      INFO  : Starting Job = job_1454394534358_0164, Tracking URL = http://hn0-hs21-h.hdinsight.net:8088/proxy/application_1454394534358_0164/
      INFO  : Kill Command = /usr/hdp/2.4.1.0-170/hadoop/bin/hadoop job  -kill job_1454394534358_0164
      INFO  : Hadoop job information for Stage-4: number of mappers: 1; number of reducers: 1
      INFO  : 2016-02-02 10:11:02,367 Stage-4 map = 0%,  reduce = 0%
      INFO  : 2016-02-02 10:11:26,060 Stage-4 map = 100%,  reduce = 0%, Cumulative CPU 5.48 sec
      INFO  : 2016-02-02 10:11:39,024 Stage-4 map = 100%,  reduce = 100%, Cumulative CPU 11.18 sec
      INFO  : MapReduce Total cumulative CPU time: 11 seconds 180 msec
      INFO  : Ended Job = job_1454394534358_0164
      INFO  : Stage-9 is selected by condition resolver.
      INFO  : Stage-1 is filtered out by condition resolver.
      ERROR : Execution failed with exit status: 2
      ERROR : Obtaining error information
      ERROR : 
      Task failed!
      Task ID:
        Stage-9
      
      Logs:
      
      ERROR : /var/log/hive/hiveServer2.log
      INFO  : Number of reduce tasks determined at compile time: 1
      INFO  : In order to change the average load for a reducer (in bytes):
      INFO  :   set hive.exec.reducers.bytes.per.reducer=<number>
      INFO  : In order to limit the maximum number of reducers:
      INFO  :   set hive.exec.reducers.max=<number>
      INFO  : In order to set a constant number of reducers:
      INFO  :   set mapreduce.job.reduces=<number>
      INFO  : number of splits:2
      INFO  : Submitting tokens for job: job_1454394534358_0169
      INFO  : Kind: HDFS_DELEGATION_TOKEN, Service: 10.0.0.36:8020, Ident: (HDFS_DELEGATION_TOKEN token 252 for hrt_qa)
      INFO  : The url to track the job: http://hn0-hs21-h.hdinsight.net:8088/proxy/application_1454394534358_0169/
      INFO  : Starting Job = job_1454394534358_0169, Tracking URL = http://hn0-hs21-h.hdinsight.net:8088/proxy/application_1454394534358_0169/
      INFO  : Kill Command = /usr/hdp/2.4.1.0-170/hadoop/bin/hadoop job  -kill job_1454394534358_0169
      INFO  : Hadoop job information for Stage-1: number of mappers: 2; number of reducers: 1
      INFO  : 2016-02-02 10:16:38,027 Stage-1 map = 0%,  reduce = 0%
      INFO  : 2016-02-02 10:16:52,498 Stage-1 map = 50%,  reduce = 0%, Cumulative CPU 3.8 sec
      INFO  : 2016-02-02 10:16:53,566 Stage-1 map = 100%,  reduce = 0%, Cumulative CPU 9.94 sec
      INFO  : 2016-02-02 10:17:16,202 Stage-1 map = 100%,  reduce = 100%, Cumulative CPU 17.04 sec
      INFO  : MapReduce Total cumulative CPU time: 17 seconds 40 msec
      INFO  : Ended Job = job_1454394534358_0169
      ERROR : Execution failed with exit status: 2
      ERROR : Obtaining error information
      ERROR : 
      Task failed!
      Task ID:
        Stage-8
      
      Logs:
      
      ERROR : /var/log/hive/hiveServer2.log
      Error: Error while processing statement: FAILED: Execution Error, return code 2 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask (state=08S01,code=2)
      Aborting command set because "force" is false and command failed: "select * 
      from studenttab10k s 
      where s.name not in 
      (select name from temp1);"
      Closing: 0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181/;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;principal=hive/_HOST@HDINSIGHT.NET;transportMode=http;httpPath=cliservice
      Its app log can be viewed at http://qelog.hortonworks.com/log/hs21-hbs24-1454382123/app-logs/application_1454394534358_0169.log
      Permalink Edit Delete 
      tsaito Takahiko Saito added a comment - 3 days ago
      The query works without 'temporary table':
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> select registration from studenttab10k s join votertab10k v
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> on (s.name = v.name) join studentparttab30k p
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> on (p.name = v.name)
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> where s.age < 25 and v.age < 25 and p.age < 25;
      Permalink Edit Delete 
      tsaito Takahiko Saito added a comment - 3 days ago
      More info about temporary table:
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> describe formatted s10k;
      +-------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--+
      |           col_name            |                                                                  data_type                                                                  |        comment        |
      +-------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--+
      | # col_name                    | data_type                                                                                                                                   | comment               |
      |                               | NULL                                                                                                                                        | NULL                  |
      | name                          | string                                                                                                                                      |                       |
      | age                           | int                                                                                                                                         |                       |
      | gpa                           | double                                                                                                                                      |                       |
      |                               | NULL                                                                                                                                        | NULL                  |
      | # Detailed Table Information  | NULL                                                                                                                                        | NULL                  |
      | Database:                     | default                                                                                                                                     | NULL                  |
      | Owner:                        | hrt_qa                                                                                                                                      | NULL                  |
      | CreateTime:                   | Tue Feb 02 23:02:31 UTC 2016                                                                                                                | NULL                  |
      | LastAccessTime:               | UNKNOWN                                                                                                                                     | NULL                  |
      | Protect Mode:                 | None                                                                                                                                        | NULL                  |
      | Retention:                    | 0                                                                                                                                           | NULL                  |
      | Location:                     | hdfs://hn0-hs21-h.hdinsight.net:8020/tmp/hive/hive/de2667ea-5bc1-4548-a4c4-97e46d6081f8/_tmp_space.db/8e8482c9-a2a4-4e8c-ad0f-2cd6e8fcdb4c  | NULL                  |
      | Table Type:                   | MANAGED_TABLE                                                                                                                               | NULL                  |
      |                               | NULL                                                                                                                                        | NULL                  |
      | # Storage Information         | NULL                                                                                                                                        | NULL                  |
      | SerDe Library:                | org.apache.hadoop.hive.ql.io.orc.OrcSerde                                                                                                   | NULL                  |
      | InputFormat:                  | org.apache.hadoop.hive.ql.io.orc.OrcInputFormat                                                                                             | NULL                  |
      | OutputFormat:                 | org.apache.hadoop.hive.ql.io.orc.OrcOutputFormat                                                                                            | NULL                  |
      | Compressed:                   | No                                                                                                                                          | NULL                  |
      | Num Buckets:                  | -1                                                                                                                                          | NULL                  |
      | Bucket Columns:               | []                                                                                                                                          | NULL                  |
      | Sort Columns:                 | []                                                                                                                                          | NULL                  |
      | Storage Desc Params:          | NULL                                                                                                                                        | NULL                  |
      |                               | serialization.format                                                                                                                        | 1                     |
      +-------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--+
      26 rows selected (0.22 seconds)
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> set hive.server2.enable.doAs;
      +---------------------------------+--+
      |               set               |
      +---------------------------------+--+
      | hive.server2.enable.doAs=false  |
      +---------------------------------+--+
      Permalink Edit Delete 
      tsaito Takahiko Saito added a comment - 3 days ago
      hdfs dir of temporary table is owned by hive as expected since hive.server2.enable.doAs=false:
      hdfs@hn0-hs21-h:~$ hdfs dfs -ls hdfs://hn0-hs21-h.hdinsight.net:8020/tmp/hive/hive/de2667ea-5bc1-4548-a4c4-97e46d6081f8/_tmp_space.db/8e8482c9-a2a4-4e8c-ad0f-2cd6e8fcdb4c
      Found 1 items
      -rwx------   3 hive hdfs      47777 2016-02-02 23:02 hdfs://hn0-hs21-h.hdinsight.net:8020/tmp/hive/hive/de2667ea-5bc1-4548-a4c4-97e46d6081f8/_tmp_space.db/8e8482c9-a2a4-4e8c-ad0f-2cd6e8fcdb4c/000000_0
      Not sure if it's related to the JIRA, but one thing I noticed was that dfs cmd throws error via beeline:
      0: jdbc:hive2://zk2-hs21-h.hdinsight.net:2181> dfs -ls hdfs://hn0-hs21-h.hdinsight.net:8020/tmp/hive/hive/de2667ea-5bc1-4548-a4c4-97e46d6081f8/_tmp_space.db/8e8482c9-a2a4-4e8c-ad0f-2cd6e8fcdb4c;
      Error: Error while processing statement: Permission denied: user [hrt_qa] does not have privilege for [DFS] command (state=,code=1)
      Permalink Edit 
      thejas Thejas Nair added a comment - 5 hours ago - edited
      Takahiko Saito 
      The above DFS error would be from Ranger of SQL standard authorization. It is not related to the test failure.
      But you are right that it looks like a permission issue.
      The issue seen in HIVE-739 also exists in this part of Hive. Hive in MR mode launches a new child process to process the small table and create a hash table. This child process needs credentials from HDFS. However, in this setup, azure fs is the default file system. We should also get delegation token from all FS URIs listed under mapreduce.job.hdfs-servers config.
      There are hueristics around when map-join gets used. That is why you don't see it unless temp table is used (that uses ORC format and might have stats as well, while the original table is probaly text format).
      https://github.com/hortonworks/hive/blob/2.4-maint/ql/src/java/org/apache/hadoop/hive/ql/exec/SecureCmdDoAs.java needs change similar to webhcat change in HIVE-739
      Permalink Edit 
      sush Sushanth Sowmyan added a comment - 7 minutes ago
      Takahiko Saito, we should file an apache jira for this as well. Would you like to do so, so the bug report has attribution to you?
      Permalink Edit Delete 
      tsaito Takahiko Saito added a comment - 4 minutes ago
      Sushanth Sowmyan I will file one and update with that JIRA.
       Comment	
      People
      Assignee:	 sush Sushanth Sowmyan
      Assign to me
      Reporter:	 tsaito Takahiko Saito
      QEAssignee:	Takahiko Saito
      Votes:	0
      Watchers:	3 Stop watching this issue 
      Dates
      Created:	3 days ago
      Updated:	4 minutes ago
      Who's Looking?
      
      Agile
      View on Board
      

      hivesever2 log shows:

      2016-02-02 18:04:43,766 ERROR [HiveServer2-Background-Pool: Thread-517]: operation.Operation (SQLOperation.java:run(209)) - Error running hive query:
      org.apache.hive.service.cli.HiveSQLException: Error while processing statement: FAILED: Execution Error, return code 2 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask
              at org.apache.hive.service.cli.operation.Operation.toSQLException(Operation.java:315)
              at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:156)
              at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:71)
              at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:206)
              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:1657)
              at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:218)
              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)
      

      Attachments

        1. HIVE-13017.3.patch
          2 kB
          Sushanth Sowmyan
        2. HIVE-13017.2.patch
          2 kB
          Sushanth Sowmyan
        3. HIVE-13017.patch
          2 kB
          Sushanth Sowmyan

        Issue Links

          Activity

            People

              sushanth Sushanth Sowmyan
              taksaito Takahiko Saito
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: