Coder Social home page Coder Social logo

vmware-archive / simple-hive Goto Github PK

View Code? Open in Web Editor NEW
5.0 15.0 2.0 175 KB

A simple Hive as-a-service and an introduction to Cloud Foundry service brokers.

License: Apache License 2.0

Kotlin 95.98% Shell 4.02%
service-broker hive cloud-foundry spring spring-boot cf-services kotlin

simple-hive's Introduction

Simple Hive

simple-hive-logo

This is a simple Hive as a service for Cloud Foundry. This is for you if you find yourself in either of these situations:

"I am developing an application and it depends on Hive. What now?"

"Somebody mentioned Cloud Foundry, services and brokers and I didn't get it."

Simple Hive is meant to be easy-to-use, for client development and testing. It is stand-alone and can be run locally or deployed to Cloud Foundry. It neither has authentication, nor authorization and data will be gone after restarting the service.

We have used the project also to explore how CF services and brokers work. We've learned a thing or two about CF and want to share.

Disclaimer:

  • this is not production-grade software
  • the service instance is not secured

Contents

(Simple) Hive

To put it in nutshell, Apache Hive provides an SQL-like interface to your Hadoop store. Usually, the required infrastructure is a little involved. You need to configure Hadoop, etc. This is where Simple Hive steps in. It abstracts all dependencies into a single runnable Spring-Boot application which can be simply deployed to any CF. All data stored in a local directory and in-memory database. All data is reset on service restart. This is not necessarily in agreement with CF's consideration for cloud-native applications. But it just works and keeps things simple.

Simple Hive is using Hive 1.2.1.

Cloud Foundry services and brokers

Let's say your app depends on a service, a database for instance. You could deploy and configure that database yourself. However, getting all the configuration right is tedious and error-prone. CF can do the heavy-lifting for you. It provides two very helpful things:

  • services: things apps can depend on, and
  • service brokers: things that manage these services for you All that is left to the application developer is to inform CF about its dependencies. The provisioning of instances and the wiring up is taken care of. Usually, one would bind apps and their services via CF's manifest.yml.

In our case, Simple Hive is the service we want to depend on. We also want a broker to manage instances of it for our applications. A broker can be any kind of application that implements the Service Broker API. Also, it can be deployed anywhere as long as we can talk to it. A broker has three responsibilities:

  • Manage a catalog of plans that your service offers, e.g. free, paid, more memory, less memory, ... (The Simple Hive broker offers only one plan. It does not incur cost.)

  • Manage service instance creation and deletion. (In our case it is the creation and deletion of a database within Simple Hive.)

  • Help apps bind and unbind themselves to and from instances of the service. (In our case it is simply about sharing the database connection url with the application. Nothing happens on unbind.)

At the time of writing and interestingly enough, the service broker API is about to be standardized. See another example of a service broker here.

The service broker is a very powerful abstraction. It is certainly not limited to databases. For example, it could just as well manage test accounts in your payment providers' sandbox.

There's a framework for implementing brokers in Java with Spring. It greatly simplifies your efforts. What you will get is a Spring Boot app that you can deploy to your CF. However, there are other ways to achieve the same goal, with Ruby for instance and deploy anywhere.

There is a deployment script for the Simple Hive service broker. However, installing a service broker on your CF is as simple as:

cf create-service-broker <brokername> <username> <password> <broker-url>

Now you can create instances of the service and bind apps to it.

Cloud connector

When we bind an app to a service instance, CF injects information about the service instance into the app's environment. Specifically, you will that information in the environment variable VCAP_SERVICES. In the case of Simple Hive it will manifest as something like this:

{
 "VCAP_SERVICES": {
  "simple-hive": [
   {
    "credentials": {
     "uri": "hive2://admin:[email protected]:80/your-db;transportMode=http;httpPath=simple-hive"
    }
   }
  ]
 }
}

Spring automatically creates DataSource beans if it has all necessary information. In order to help turn Hive's URI into a DataSource bean we have implemented a HiveDataSourceCreator and registered it in Spring Cloud Connectors. The connector is situated in its own module hive-connector.

Spring Cloud Connectors has some built-in service creators for the the most popular use-cases, e.g. Postgres, SMTP, etc. If your service is not included you can build your own. Refer to the documentation for guidance.

A sample client

The sample client showcases all parties in action; Simple Hive, its broker and a client. Its purpose is to record ping pong wins for players. It writes wins to Simple Hive and reads a count from it. (btw You don't need the sample client to run Simple Hive.)

Let's say you deployed everything(./deploy.sh) to your PCF dev and the sample client is reachable at sample-client.local.pcfdev.io. Let's say Alfred has won a game of ping pong. We can record Alfred's win like so:

curl -XPOST http://sample-client.local.pcfdev.io/alfred

We can get a count of his wins by GETting the same endpoint:

curl -XGET http://sample-client.local.pcfdev.io/alfred

Under the hood, the sample client is relying on the automatically provided JdbcTemplate bean. It itself has no knowledge of where or what Simple Hive is. Cloud Foundry and Spring hide all those details.

Usage & deployment

You can easily deploy the service, broker and sample client to any CF. Assuming your logged in to CF, run the deployment script:

./deploy.sh

You can also deploy each party individually:

./service/deploy.sh

./broker/deploy.sh  

./sample-client/deploy.sh

You can confirm your deployment with ./test.sh. Or play with the sample client yourself:

$ curl -XPOST http://sample-client.local.pcfdev.io/alfred
$ curl -XPOST http://sample-client.local.pcfdev.io/alfred
$ curl -XGET http://sample-client.local.pcfdev.io/alfred
2

You can configure the admin password for the broker by setting BROKER_ADMIN_PASSWORD. Otherwise, it's a random password which appears on stdout when deploying:

### Attention: BROKER_ADMIN_PASSWORD set to: 25184

simple-hive's People

Contributors

kvmw avatar

Stargazers

 avatar  avatar  avatar  avatar  avatar

Watchers

 avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar

simple-hive's Issues

Cannot use JOIN

Hi,

Thanks for simple-hive. It's been great for quickly getting Hive running on CF infrastructure that does not support Docker.

We're running into an issue where any query using a JOIN fails.

set hive.execution.engine=mr;
SELECT * FROM A JOIN B ON B.id = A.b_id;
2017-01-23T12:25:08.67+0000 [APP/0]      OUT 2017-01-23 12:25:08.668  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:25:08.75+0000 [APP/0]      OUT 2017-01-23 12:25:08.754  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:25:08.75+0000 [APP/0]      OUT 2017-01-23 12:25:08.755  INFO 20 --- [Pool: Thread-35] o.a.h.service.cli.operation.Operation    : Putting temp output to file /home/vcap/tmp/hive8156245218269664233/localScratch/998589d1-425e-4e06-9
3e0-c332351143bb928185943743737458.pipeout
2017-01-23T12:25:08.77+0000 [APP/0]      OUT 2017-01-23 12:25:08.775  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:25:08.86+0000 [APP/0]      OUT 2017-01-23 12:25:08.860  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:25:08.88+0000 [APP/0]      OUT 2017-01-23 12:25:08.885  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:25:08.97+0000 [APP/0]      OUT 2017-01-23 12:25:08.974  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:25:14.82+0000 [APP/0]      OUT 2017-01-23 12:25:14.820  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.905  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.906  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=compile from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.907  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=parse from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.907  INFO 20 --- [Pool: Thread-35] hive.ql.parse.ParseDriver                : Parsing command: SELECT p.objectid FROM opportunitystaff p JOIN opportunit76630dff c ON c.objectid=p
.type_id
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.907  INFO 20 --- [Pool: Thread-35] hive.ql.parse.ParseDriver                : Parse Completed
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.907  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=parse start=1485174314907 end=1485174314907 duration=0 from=org.apache.hadoop.hive.
ql.Driver>
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.907  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=semanticAnalyze from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.908  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Starting Semantic Analysis
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.908  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Completed phase 1 of Semantic Analysis
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.908  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Get metadata for source tables
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.908  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.metastore.HiveMetaStore  : 17: get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl=opportunitystaff
2017-01-23T12:25:14.90+0000 [APP/0]      OUT 2017-01-23 12:25:14.908  INFO 20 --- [Pool: Thread-35] o.a.h.h.metastore.HiveMetaStore.audit    : ugi=admin        ip=unknown-ip-addr      cmd=get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl
=opportunitystaff
2017-01-23T12:25:14.92+0000 [APP/0]      OUT 2017-01-23 12:25:14.922  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.metastore.HiveMetaStore  : 17: get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl=opportunit76630dff
2017-01-23T12:25:14.92+0000 [APP/0]      OUT 2017-01-23 12:25:14.922  INFO 20 --- [Pool: Thread-35] o.a.h.h.metastore.HiveMetaStore.audit    : ugi=admin        ip=unknown-ip-addr      cmd=get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl
=opportunit76630dff
2017-01-23T12:25:14.93+0000 [APP/0]      OUT 2017-01-23 12:25:14.930  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Get metadata for subqueries
2017-01-23T12:25:14.93+0000 [APP/0]      OUT 2017-01-23 12:25:14.931  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Get metadata for destination tables
2017-01-23T12:25:14.93+0000 [APP/0]      OUT 2017-01-23 12:25:14.934  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Completed getting MetaData in Semantic Analysis
2017-01-23T12:25:14.93+0000 [APP/0]      OUT 2017-01-23 12:25:14.936  INFO 20 --- [Pool: Thread-35] org.apache.hadoop.hive.common.FileUtils  : Creating directory if it doesn't exist: file:/home/vcap/tmp/hive8156245218269664233/localScratch/998
589d1-425e-4e06-93e0-c332351143bb/hive_2017-01-23_12-25-14_906_3555154913006934385-3/-mr-10000/.hive-staging_hive_2017-01-23_12-25-14_906_3555154913006934385-3
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.961  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Set stats collection dir : file:/home/vcap/tmp/hive8156245218269664233/localScratch/998589d1-425e-4e
06-93e0-c332351143bb/hive_2017-01-23_12-25-14_906_3555154913006934385-3/-mr-10000/.hive-staging_hive_2017-01-23_12-25-14_906_3555154913006934385-3/-ext-10002
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.964  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FS(290)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.964  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for SEL(289)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.964  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for JOIN(288)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.964  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for RS(285)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.964  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FIL(284)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : p
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  type_id is not null
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for TS(282)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of TS For Alias : p
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  type_id is not null
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for RS(287)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FIL(286)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : c
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  objectid is not null
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.965  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for TS(283)
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.966  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of TS For Alias : c
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.966  INFO 20 --- [Pool: Thread-35] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  objectid is not null
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.967  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=partition-retrieving from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.967  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=partition-retrieving start=1485174314966 end=1485174314967 duration=1 from=org.apac
he.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.967  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=partition-retrieving from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.967  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=partition-retrieving start=1485174314967 end=1485174314967 duration=0 from=org.apac
he.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.967  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.ColumnPrunerProcFactory      : JOIN 288 oldExprs: {0=[Column[VALUE._col0], Column[VALUE._col1], Column[VALUE._col2], Column[VALUE._
col3], Column[VALUE._col4], Column[VALUE._col5], Column[VALUE._col6], Column[VALUE._col7], Column[VALUE._col8], Column[VALUE._col9], Column[VALUE._col10], Column[VALUE._col11], Column[VALUE._col12], Column[VALUE._col13], Column[VALUE._col14],
Column[KEY.reducesinkkey0], Column[VALUE._col15], Column[VALUE._col16], Column[VALUE._col17], Column[VALUE._col18], Column[VALUE._col19], Column[VALUE._col20], Column[VALUE._col21]], 1=[Column[KEY.reducesinkkey0], Column[VALUE._col0], Column[V
ALUE._col1], Column[VALUE._col2], Column[VALUE._col3], Column[VALUE._col4], Column[VALUE._col5], Column[VALUE._col6], Column[VALUE._col7], Column[VALUE._col8], Column[VALUE._col9], Column[VALUE._col10], Column[VALUE._col11], Column[VALUE._col1
2], Column[VALUE._col13], Column[VALUE._col14], Column[VALUE._col15], Column[VALUE._col16]]}
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.967  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.ColumnPrunerProcFactory      : JOIN 288 newExprs: {0=[Column[VALUE._col0]], 1=[]}
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.967  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 285 oldColExprMap: {VALUE._col20=Column[INPUT__FILE__NAME], VALUE._col10=Column[shortdescription]
, VALUE._col21=Column[ROW__ID], VALUE._col11=Column[opportunity_id], VALUE._col12=Column[modifiedbyuser_id], KEY.reducesinkkey0=Column[type_id], VALUE._col2=Column[modifiedutc], VALUE._col3=Column[createdutc], VALUE._col4=Column[isdeleted], VA
LUE._col5=Column[display], VALUE._col0=Column[objectid], VALUE._col1=Column[objectclass], VALUE._col13=Column[originalsystem_id], VALUE._col14=Column[createdbyuser_id], VALUE._col15=Column[staffofficer_id], VALUE._col16=Column[contributid6c8f3
27], VALUE._col6=Column[display_u], VALUE._col17=Column[team_id], VALUE._col7=Column[sendnotification], VALUE._col18=Column[contributic200615c], VALUE._col8=Column[acl], VALUE._col19=Column[BLOCK__OFFSET__INSIDE__FILE], VALUE._col9=Column[cont
ributi7232ff8d]}
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.968  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 285 newColExprMap: {KEY.reducesinkkey0=Column[type_id], VALUE._col0=Column[objectid]}
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.968  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 287 oldColExprMap: {VALUE._col10=Column[rank], VALUE._col11=Column[modifiedbyuser_id], VALUE._col
12=Column[originalsystem_id], KEY.reducesinkkey0=Column[objectid], VALUE._col2=Column[createdutc], VALUE._col3=Column[isdeleted], VALUE._col4=Column[display], VALUE._col5=Column[display_u], VALUE._col0=Column[objectclass], VALUE._col1=Column[m
odifiedutc], VALUE._col13=Column[createdbyuser_id], VALUE._col14=Column[BLOCK__OFFSET__INSIDE__FILE], VALUE._col15=Column[INPUT__FILE__NAME], VALUE._col16=Column[ROW__ID], VALUE._col6=Column[sendnotification], VALUE._col7=Column[acl], VALUE._c
ol8=Column[name], VALUE._col9=Column[name_u]}
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.968  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 287 newColExprMap: {KEY.reducesinkkey0=Column[objectid]}
2017-01-23T12:25:14.96+0000 [APP/0]      OUT 2017-01-23 12:25:14.969  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=getInputSummary from=org.apache.hadoop.hive.ql.exec.Utilities>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.970  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.exec.Utilities   : Cache Content Summary for file:/home/vcap/tmp/hive8156245218269664233/warehouse/b8e90977_fcff_4ab8_a
ae5_b1c7c74d34a6.db/opportunit76630dff length: 0 file count: 0 directory count: 1
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.970  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.exec.Utilities   : Cache Content Summary for file:/home/vcap/tmp/hive8156245218269664233/warehouse/b8e90977_fcff_4ab8_a
ae5_b1c7c74d34a6.db/opportunitystaff length: 0 file count: 0 directory count: 1
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.970  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=getInputSummary start=1485174314969 end=1485174314970 duration=1 from=org.apache.ha
doop.hive.ql.exec.Utilities>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.971  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.p.LocalMapJoinProcFactory    : Setting max memory usage to 0.9 for table sink not followed by group by
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.971  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Looking for table scans where optimization is applicable
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.971  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Found 0 null table scans
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.972  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Looking for table scans where optimization is applicable
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.972  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Found 0 null table scans
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.972  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Looking for table scans where optimization is applicable
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.972  INFO 20 --- [Pool: Thread-35] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Found 0 null table scans
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.972  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.parse.SemanticAnalyzer     : Completed plan generation
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.972  INFO 20 --- [Pool: Thread-35] org.apache.hadoop.hive.ql.Driver         : Semantic Analysis Completed
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.972  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=semanticAnalyze start=1485174314907 end=1485174314972 duration=65 from=org.apache.h
adoop.hive.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.973  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.exec.ListSinkOperator      : Initializing operator OP[296]
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.973  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.exec.ListSinkOperator      : Initialization Done 296 OP
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.973  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.exec.ListSinkOperator      : Operator 296 OP initialized
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.973  INFO 20 --- [Pool: Thread-35] org.apache.hadoop.hive.ql.Driver         : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:p.objectid, type:string, comment:null)]
, properties:null)
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.973  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=compile start=1485174314906 end=1485174314973 duration=67 from=org.apache.hadoop.hi
ve.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.974  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=Driver.run from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.974  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=TimeToSubmit from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.974  INFO 20 --- [ool: Thread-631] org.apache.hadoop.hive.ql.Driver         : Concurrency mode is disabled, not creating a lock manager
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.974  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=Driver.execute from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.974  INFO 20 --- [ool: Thread-631] org.apache.hadoop.hive.ql.Driver         : Starting command(queryId=vcap_20170123122514_49622150-113e-485d-a0a0-8e99bd39f8d2): SELECT p.objecti
d FROM opportunitystaff p JOIN opportunit76630dff c ON c.objectid=p.type_id
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.975  INFO 20 --- [ool: Thread-631] org.apache.hadoop.hive.ql.Driver         : Query ID = vcap_20170123122514_49622150-113e-485d-a0a0-8e99bd39f8d2
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.975  INFO 20 --- [ool: Thread-631] org.apache.hadoop.hive.ql.Driver         : Total jobs = 1
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.975  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=TimeToSubmit start=1485174314974 end=1485174314975 duration=1 from=org.apache.hadoo
p.hive.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.975  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.975  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=task.MAPREDLOCAL.Stage-4 from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:14.97+0000 [APP/0]      OUT 2017-01-23 12:25:14.977  INFO 20 --- [ool: Thread-631] org.apache.hadoop.hive.ql.Driver         : Starting task [Stage-4:MAPREDLOCAL] in serial mode
2017-01-23T12:25:14.98+0000 [APP/0]      OUT 2017-01-23 12:25:14.981  INFO 20 --- [ool: Thread-631] o.a.h.hive.ql.exec.mr.MapredLocalTask    : Generating plan file file:/home/vcap/tmp/hive8156245218269664233/localScratch/998589d1-425e-4e06-93e
0-c332351143bb/hive_2017-01-23_12-25-14_906_3555154913006934385-22/-local-10005/plan.xml
2017-01-23T12:25:14.98+0000 [APP/0]      OUT 2017-01-23 12:25:14.984  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=serializePlan from=org.apache.hadoop.hive.ql.exec.Utilities>
2017-01-23T12:25:14.98+0000 [APP/0]      OUT 2017-01-23 12:25:14.984  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.exec.Utilities   : Serializing MapredLocalWork via kryo
2017-01-23T12:25:14.99+0000 [APP/0]      OUT 2017-01-23 12:25:14.990  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=serializePlan start=1485174314984 end=1485174314990 duration=6 from=org.apache.hado
op.hive.ql.exec.Utilities>
2017-01-23T12:25:15.00+0000 [APP/0]      OUT 2017-01-23 12:25:15.004  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:25:15.09+0000 [APP/0]      OUT 2017-01-23 12:25:15.092  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:25:15.09+0000 [APP/0]      OUT 2017-01-23 12:25:15.095  INFO 20 --- [ool: Thread-631] o.a.h.hive.ql.exec.mr.MapredLocalTask    : Executing: /dev/null-hadoop-bin jar /home/vcap/app/BOOT-INF/lib/hive-common-1.2.1.jar org.apache.had
oop.hive.ql.exec.mr.ExecDriver -localtask -plan file:/home/vcap/tmp/hive8156245218269664233/localScratch/998589d1-425e-4e06-93e0-c332351143bb/hive_2017-01-23_12-25-14_906_3555154913006934385-22/-local-10005/plan.xml   -jobconffile file:/home/v
cap/tmp/hive8156245218269664233/localScratch/998589d1-425e-4e06-93e0-c332351143bb/hive_2017-01-23_12-25-14_906_3555154913006934385-22/-local-10006/jobconf.xml
2017-01-23T12:25:15.09+0000 [APP/0]      OUT 2017-01-23 12:25:15.097 ERROR 20 --- [ool: Thread-631] o.a.h.hive.ql.exec.mr.MapredLocalTask    : Exception: java.io.IOException: Cannot run program "/dev/null-hadoop-bin" (in directory "/home/vcap/
app"): error=2, No such file or directory
2017-01-23T12:25:15.09+0000 [APP/0]      OUT java.io.IOException: Cannot run program "/dev/null-hadoop-bin" (in directory "/home/vcap/app"): error=2, No such file or directory
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.ProcessBuilder.start(ProcessBuilder.java:1048) ~[na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.Runtime.exec(Runtime.java:620) ~[na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.Runtime.exec(Runtime.java:450) ~[na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask.executeInChildVM(MapredLocalTask.java:289) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask.execute(MapredLocalTask.java:138) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:160) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:88) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1653) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1412) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1195) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1059) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1054) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:154) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:71) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:206) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.security.AccessController.doPrivileged(Native Method) [na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at javax.security.auth.Subject.doAs(Subject.java:422) [na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1628) [hadoop-common-2.6.0.jar!/:na]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:218) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT Caused by: java.io.IOException: error=2, No such file or directory
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.UNIXProcess.forkAndExec(Native Method) ~[na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.UNIXProcess.<init>(UNIXProcess.java:248) ~[na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.ProcessImpl.start(ProcessImpl.java:134) ~[na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    at java.lang.ProcessBuilder.start(ProcessBuilder.java:1029) ~[na:1.8.0_91]
2017-01-23T12:25:15.09+0000 [APP/0]      OUT    ... 23 common frames omitted
2017-01-23T12:25:15.09+0000 [APP/0]      OUT 2017-01-23 12:25:15.098 ERROR 20 --- [ool: Thread-631] org.apache.hadoop.hive.ql.Driver         : FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask
2017-01-23T12:25:15.10+0000 [APP/0]      OUT 2017-01-23 12:25:15.098  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=Driver.execute start=1485174314974 end=1485174315098 duration=124 from=org.apache.h
adoop.hive.ql.Driver>
2017-01-23T12:25:15.10+0000 [APP/0]      OUT 2017-01-23 12:25:15.098  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:15.10+0000 [APP/0]      OUT 2017-01-23 12:25:15.098  INFO 20 --- [ool: Thread-631] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=releaseLocks start=1485174315098 end=1485174315098 duration=0 from=org.apache.hadoo
p.hive.ql.Driver>
2017-01-23T12:25:15.10+0000 [APP/0]      OUT 2017-01-23 12:25:15.098 ERROR 20 --- [ool: Thread-631] o.a.h.service.cli.operation.Operation    : Error running hive query:
2017-01-23T12:25:15.10+0000 [APP/0]      OUT org.apache.hive.service.cli.HiveSQLException: Error while processing statement: FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.mr.MapredLocalTask
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.Operation.toSQLException(Operation.java:315) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:156) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:71) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:206) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at java.security.AccessController.doPrivileged(Native Method) [na:1.8.0_91]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at javax.security.auth.Subject.doAs(Subject.java:422) [na:1.8.0_91]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1628) [hadoop-common-2.6.0.jar!/:na]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:218) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
2017-01-23T12:25:15.10+0000 [APP/0]      OUT    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2017-01-23T12:25:15.12+0000 [APP/0]      OUT 2017-01-23 12:25:15.128  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:25:15.21+0000 [APP/0]      OUT 2017-01-23 12:25:15.216  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:25:15.21+0000 [APP/0]      OUT 2017-01-23 12:25:15.217  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.exec.ListSinkOperator      : 296 finished. closing...
2017-01-23T12:25:15.21+0000 [APP/0]      OUT 2017-01-23 12:25:15.217  INFO 20 --- [Pool: Thread-35] o.a.h.hive.ql.exec.ListSinkOperator      : 296 Close done
2017-01-23T12:25:15.21+0000 [APP/0]      OUT 2017-01-23 12:25:15.219  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:25:15.21+0000 [APP/0]      OUT 2017-01-23 12:25:15.219  INFO 20 --- [Pool: Thread-35] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=releaseLocks start=1485174315219 end=1485174315219 duration=0 from=org.apache.hadoo
p.hive.ql.Driver>

This seems to be because the hadoop binary cannot be found (it is set to /dev/null). We changed it to /dev/null-hadoop-bin to confirm this.

Switching to execution engine Tez we get a slightly different error (I suspect that the hadoop bin thing could be hard to overcome, but this error may be easier to solve).

set hive.execution.engine=tez;
SELECT * FROM A JOIN B ON B.id = A.b_id;
2017-01-23T12:23:44.34+0000 [APP/0]      OUT 2017-01-23 12:23:44.340  INFO 20 --- [Pool: Thread-36] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:23:44.42+0000 [APP/0]      OUT 2017-01-23 12:23:44.428  INFO 20 --- [Pool: Thread-36] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:23:44.42+0000 [APP/0]      OUT 2017-01-23 12:23:44.429  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=compile from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=parse from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] hive.ql.parse.ParseDriver                : Parsing command: SELECT p.objectid FROM opportunitystaff p JOIN opportunit76630dff c ON c.objectid=p
.type_id
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] hive.ql.parse.ParseDriver                : Parse Completed
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=parse start=1485174224430 end=1485174224430 duration=0 from=org.apache.hadoop.hive.
ql.Driver>
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=semanticAnalyze from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Starting Semantic Analysis
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Completed phase 1 of Semantic Analysis
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.430  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Get metadata for source tables
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.431  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.metastore.HiveMetaStore  : 4: get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl=opportunitystaff
2017-01-23T12:23:44.43+0000 [APP/0]      OUT 2017-01-23 12:23:44.431  INFO 20 --- [Pool: Thread-36] o.a.h.h.metastore.HiveMetaStore.audit    : ugi=admin        ip=unknown-ip-addr      cmd=get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl
=opportunitystaff
2017-01-23T12:23:44.44+0000 [APP/0]      OUT 2017-01-23 12:23:44.440  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.metastore.HiveMetaStore  : 4: get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl=opportunit76630dff
2017-01-23T12:23:44.44+0000 [APP/0]      OUT 2017-01-23 12:23:44.440  INFO 20 --- [Pool: Thread-36] o.a.h.h.metastore.HiveMetaStore.audit    : ugi=admin        ip=unknown-ip-addr      cmd=get_table : db=b8e90977_fcff_4ab8_aae5_b1c7c74d34a6 tbl
=opportunit76630dff
2017-01-23T12:23:44.44+0000 [APP/0]      OUT 2017-01-23 12:23:44.448  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Get metadata for subqueries
2017-01-23T12:23:44.44+0000 [APP/0]      OUT 2017-01-23 12:23:44.448  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Get metadata for destination tables
2017-01-23T12:23:44.45+0000 [APP/0]      OUT 2017-01-23 12:23:44.452  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Completed getting MetaData in Semantic Analysis
2017-01-23T12:23:44.45+0000 [APP/0]      OUT 2017-01-23 12:23:44.456  INFO 20 --- [Pool: Thread-36] org.apache.hadoop.hive.common.FileUtils  : Creating directory if it doesn't exist: file:/home/vcap/tmp/hive8156245218269664233/localScratch/998
589d1-425e-4e06-93e0-c332351143bb/hive_2017-01-23_12-23-44_429_3403078215150409173-1/-mr-10000/.hive-staging_hive_2017-01-23_12-23-44_429_3403078215150409173-1
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.481  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Set stats collection dir : file:/home/vcap/tmp/hive8156245218269664233/localScratch/998589d1-425e-4e
06-93e0-c332351143bb/hive_2017-01-23_12-23-44_429_3403078215150409173-1/-mr-10000/.hive-staging_hive_2017-01-23_12-23-44_429_3403078215150409173-1/-ext-10002
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FS(274)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for SEL(273)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for JOIN(272)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for RS(269)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FIL(275)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : p
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  (type_id) IN (RS[271])
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.485  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FIL(268)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.486  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : p
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.486  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  type_id is not null
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.486  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : p
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.486  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  (type_id) IN (RS[271])
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.486  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for TS(266)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.486  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of TS For Alias : p
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.486  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  type_id is not null
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.487  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  (type_id) IN (RS[271])
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.487  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for RS(271)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.487  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FIL(276)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.487  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : c
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.487  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  (objectid) IN (RS[269])
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.487  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for FIL(270)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.488  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : c
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.488  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  objectid is not null
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.488  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of FIL For Alias : c
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.489  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  (objectid) IN (RS[269])
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.489  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Processing for TS(267)
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.489  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     : Pushdown Predicates of TS For Alias : c
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.489  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  objectid is not null
2017-01-23T12:23:44.48+0000 [APP/0]      OUT 2017-01-23 12:23:44.489  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.ppd.OpProcFactory     :  (objectid) IN (RS[269])
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.490  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=partition-retrieving from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.490  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=partition-retrieving start=1485174224490 end=1485174224490 duration=0 from=org.apac
he.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.490  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=partition-retrieving from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.490  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=partition-retrieving start=1485174224490 end=1485174224490 duration=0 from=org.apac
he.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.491  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.ColumnPrunerProcFactory      : JOIN 272 oldExprs: {0=[Column[VALUE._col0], Column[VALUE._col1], Column[VALUE._col2], Column[VALUE._
col3], Column[VALUE._col4], Column[VALUE._col5], Column[VALUE._col6], Column[VALUE._col7], Column[VALUE._col8], Column[VALUE._col9], Column[VALUE._col10], Column[VALUE._col11], Column[VALUE._col12], Column[VALUE._col13], Column[VALUE._col14],
Column[KEY.reducesinkkey0], Column[VALUE._col15], Column[VALUE._col16], Column[VALUE._col17], Column[VALUE._col18], Column[VALUE._col19], Column[VALUE._col20], Column[VALUE._col21]], 1=[Column[KEY.reducesinkkey0], Column[VALUE._col0], Column[V
ALUE._col1], Column[VALUE._col2], Column[VALUE._col3], Column[VALUE._col4], Column[VALUE._col5], Column[VALUE._col6], Column[VALUE._col7], Column[VALUE._col8], Column[VALUE._col9], Column[VALUE._col10], Column[VALUE._col11], Column[VALUE._col1
2], Column[VALUE._col13], Column[VALUE._col14], Column[VALUE._col15], Column[VALUE._col16]]}
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.491  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.ColumnPrunerProcFactory      : JOIN 272 newExprs: {0=[Column[VALUE._col0]], 1=[]}
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.491  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 269 oldColExprMap: {VALUE._col20=Column[INPUT__FILE__NAME], VALUE._col10=Column[shortdescription]
, VALUE._col21=Column[ROW__ID], VALUE._col11=Column[opportunity_id], VALUE._col12=Column[modifiedbyuser_id], KEY.reducesinkkey0=Column[type_id], VALUE._col2=Column[modifiedutc], VALUE._col3=Column[createdutc], VALUE._col4=Column[isdeleted], VA
LUE._col5=Column[display], VALUE._col0=Column[objectid], VALUE._col1=Column[objectclass], VALUE._col13=Column[originalsystem_id], VALUE._col14=Column[createdbyuser_id], VALUE._col15=Column[staffofficer_id], VALUE._col16=Column[contributid6c8f3
27], VALUE._col6=Column[display_u], VALUE._col17=Column[team_id], VALUE._col7=Column[sendnotification], VALUE._col18=Column[contributic200615c], VALUE._col8=Column[acl], VALUE._col19=Column[BLOCK__OFFSET__INSIDE__FILE], VALUE._col9=Column[cont
ributi7232ff8d]}
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.491  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 269 newColExprMap: {KEY.reducesinkkey0=Column[type_id], VALUE._col0=Column[objectid]}
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.491  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 271 oldColExprMap: {VALUE._col10=Column[rank], VALUE._col11=Column[modifiedbyuser_id], VALUE._col
12=Column[originalsystem_id], KEY.reducesinkkey0=Column[objectid], VALUE._col2=Column[createdutc], VALUE._col3=Column[isdeleted], VALUE._col4=Column[display], VALUE._col5=Column[display_u], VALUE._col0=Column[objectclass], VALUE._col1=Column[m
odifiedutc], VALUE._col13=Column[createdbyuser_id], VALUE._col14=Column[BLOCK__OFFSET__INSIDE__FILE], VALUE._col15=Column[INPUT__FILE__NAME], VALUE._col16=Column[ROW__ID], VALUE._col6=Column[sendnotification], VALUE._col7=Column[acl], VALUE._c
ol8=Column[name], VALUE._col9=Column[name_u]}
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.491  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.ColumnPrunerProcFactory      : RS 271 newColExprMap: {KEY.reducesinkkey0=Column[objectid]}
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.494  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.SetReducerParallelism        : Set parallelism for reduce sink RS[269] to: 1
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.494  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.SetReducerParallelism        : Set parallelism for reduce sink RS[271] to: 1
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.494  INFO 20 --- [Pool: Thread-36] o.a.h.h.ql.optimizer.ConvertJoinMapJoin  : Estimated number of buckets 1
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.494  INFO 20 --- [Pool: Thread-36] o.a.h.h.ql.optimizer.ConvertJoinMapJoin  : Convert to non-bucketed map join
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.495  INFO 20 --- [Pool: Thread-36] o.a.hadoop.hive.ql.parse.TezCompiler     : Cycle free: true
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.496  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.ReduceSinkMapJoinProc        : Mapjoin MAPJOIN[279], pos: 1 --> Map 2 (1 keys estimated from 1 rows, 1 buckets)
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.496  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Looking for table scans where optimization is applicable
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.496  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Found 0 null table scans
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.496  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Looking for table scans where optimization is applicable
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.496  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Found 0 null table scans
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.496  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Looking for table scans where optimization is applicable
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.496  INFO 20 --- [Pool: Thread-36] o.a.h.h.q.o.p.NullScanTaskDispatcher     : Found 0 null table scans
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.497  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.parse.SemanticAnalyzer     : Completed plan generation
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.497  INFO 20 --- [Pool: Thread-36] org.apache.hadoop.hive.ql.Driver         : Semantic Analysis Completed
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.497  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=semanticAnalyze start=1485174224430 end=1485174224497 duration=67 from=org.apache.h
adoop.hive.ql.Driver>
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.499  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.exec.ListSinkOperator      : Initializing operator OP[281]
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.499  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.exec.ListSinkOperator      : Initialization Done 281 OP
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.499  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.exec.ListSinkOperator      : Operator 281 OP initialized
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.499  INFO 20 --- [Pool: Thread-36] org.apache.hadoop.hive.ql.Driver         : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:p.objectid, type:string, comment:null)]
, properties:null)
2017-01-23T12:23:44.49+0000 [APP/0]      OUT 2017-01-23 12:23:44.499  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=compile start=1485174224429 end=1485174224499 duration=70 from=org.apache.hadoop.hi
ve.ql.Driver>
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=Driver.run from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=TimeToSubmit from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.Driver         : Concurrency mode is disabled, not creating a lock manager
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=Driver.execute from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.Driver         : Starting command(queryId=vcap_20170123122344_35756415-35ef-4ce9-8c5c-2031f78c6d79): SELECT p.objecti
d FROM opportunitystaff p JOIN opportunit76630dff c ON c.objectid=p.type_id
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.Driver         : Query ID = vcap_20170123122344_35756415-35ef-4ce9-8c5c-2031f78c6d79
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.Driver         : Total jobs = 1
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=TimeToSubmit start=1485174224500 end=1485174224500 duration=0 from=org.apache.hadoo
p.hive.ql.Driver>
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.500  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=task.TEZ.Stage-1 from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.501  INFO 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.Driver         : Launching Job 1 out of 1
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.501  INFO 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.Driver         : Starting task [Stage-1:MAPRED] in serial mode
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.501  INFO 20 --- [ool: Thread-618] o.a.h.h.q.e.tez.TezSessionPoolManager    : The current user: admin, session user: admin
2017-01-23T12:23:44.50+0000 [APP/0]      OUT 2017-01-23 12:23:44.501  INFO 20 --- [ool: Thread-618] o.a.h.h.q.e.tez.TezSessionPoolManager    : Current queue name is null incoming queue name is null
2017-01-23T12:23:44.52+0000 [APP/0]      OUT 2017-01-23 12:23:44.520  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:23:44.55+0000 [APP/0]      OUT 2017-01-23 12:23:44.556  INFO 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.exec.Task      : Tez session hasn't been created yet. Opening session
2017-01-23T12:23:44.55+0000 [APP/0]      OUT 2017-01-23 12:23:44.556  INFO 20 --- [ool: Thread-618] o.a.h.hive.ql.exec.tez.TezSessionState   : User of session id 1e7e6e5d-9994-4b6f-ba15-0b2a8e09424a is admin
2017-01-23T12:23:44.55+0000 [APP/0]      OUT 2017-01-23 12:23:44.558  INFO 20 --- [ool: Thread-618] o.a.hadoop.hive.ql.exec.tez.DagUtils     : Hive jar directory is /home/vcap/tmp/hive8156245218269664233/tezInstallation
2017-01-23T12:23:44.56+0000 [APP/0]      OUT 2017-01-23 12:23:44.560 ERROR 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.exec.Task      : Failed to execute tez graph.
2017-01-23T12:23:44.56+0000 [APP/0]      OUT java.lang.IllegalArgumentException: java.net.URISyntaxException: Relative path in absolute URI: jar:file:/home/vcap/app/BOOT-INF/lib/hive-exec-1.2.1.jar!
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.fs.Path.initialize(Path.java:206) ~[hadoop-common-2.6.0.jar!/:na]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.fs.Path.<init>(Path.java:172) ~[hadoop-common-2.6.0.jar!/:na]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.tez.TezSessionState.createJarLocalResource(TezSessionState.java:331) ~[hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.tez.TezSessionState.open(TezSessionState.java:151) ~[hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.tez.TezTask.updateSession(TezTask.java:239) ~[hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.tez.TezTask.execute(TezTask.java:137) ~[hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:160) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:88) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1653) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1412) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1195) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1059) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1054) [hive-exec-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:154) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:71) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:206) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.security.AccessController.doPrivileged(Native Method) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at javax.security.auth.Subject.doAs(Subject.java:422) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1628) [hadoop-common-2.6.0.jar!/:na]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:218) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT Caused by: java.net.URISyntaxException: Relative path in absolute URI: jar:file:/home/vcap/app/BOOT-INF/lib/hive-exec-1.2.1.jar!
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.net.URI.checkPath(URI.java:1823) ~[na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.net.URI.<init>(URI.java:745) ~[na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.fs.Path.initialize(Path.java:203) ~[hadoop-common-2.6.0.jar!/:na]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    ... 24 common frames omitted
2017-01-23T12:23:44.56+0000 [APP/0]      OUT 2017-01-23 12:23:44.561 ERROR 20 --- [ool: Thread-618] org.apache.hadoop.hive.ql.Driver         : FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.tez.TezTask
2017-01-23T12:23:44.56+0000 [APP/0]      OUT 2017-01-23 12:23:44.561  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=Driver.execute start=1485174224500 end=1485174224561 duration=61 from=org.apache.ha
doop.hive.ql.Driver>
2017-01-23T12:23:44.56+0000 [APP/0]      OUT 2017-01-23 12:23:44.561  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.56+0000 [APP/0]      OUT 2017-01-23 12:23:44.561  INFO 20 --- [ool: Thread-618] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=releaseLocks start=1485174224561 end=1485174224561 duration=0 from=org.apache.hadoo
p.hive.ql.Driver>
2017-01-23T12:23:44.56+0000 [APP/0]      OUT 2017-01-23 12:23:44.562 ERROR 20 --- [ool: Thread-618] o.a.h.service.cli.operation.Operation    : Error running hive query:
2017-01-23T12:23:44.56+0000 [APP/0]      OUT 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
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.Operation.toSQLException(Operation.java:315) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:156) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:71) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:206) ~[hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.security.AccessController.doPrivileged(Native Method) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at javax.security.auth.Subject.doAs(Subject.java:422) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1628) [hadoop-common-2.6.0.jar!/:na]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:218) [hive-service-1.2.1.jar!/:1.2.1]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
2017-01-23T12:23:44.56+0000 [APP/0]      OUT    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2017-01-23T12:23:44.60+0000 [APP/0]      OUT 2017-01-23 12:23:44.608  INFO 20 --- [Pool: Thread-35] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:23:44.64+0000 [APP/0]      OUT 2017-01-23 12:23:44.643  INFO 20 --- [Pool: Thread-36] o.a.h.s.cli.thrift.ThriftHttpServlet     : Could not validate cookie sent, will try to generate a new cookie
2017-01-23T12:23:44.73+0000 [APP/0]      OUT 2017-01-23 12:23:44.733  INFO 20 --- [Pool: Thread-36] o.a.h.s.cli.thrift.ThriftHttpServlet     : Cookie added for clientUserName admin
2017-01-23T12:23:44.73+0000 [APP/0]      OUT 2017-01-23 12:23:44.733  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.exec.ListSinkOperator      : 281 finished. closing...
2017-01-23T12:23:44.73+0000 [APP/0]      OUT 2017-01-23 12:23:44.733  INFO 20 --- [Pool: Thread-36] o.a.h.hive.ql.exec.ListSinkOperator      : 281 Close done
2017-01-23T12:23:44.73+0000 [APP/0]      OUT 2017-01-23 12:23:44.736  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : <PERFLOG method=releaseLocks from=org.apache.hadoop.hive.ql.Driver>
2017-01-23T12:23:44.73+0000 [APP/0]      OUT 2017-01-23 12:23:44.736  INFO 20 --- [Pool: Thread-36] o.apache.hadoop.hive.ql.log.PerfLogger   : </PERFLOG method=releaseLocks start=1485174224736 end=1485174224736 duration=0 from=org.apache.hadoo
p.hive.ql.Driver>

Here the error appears to be: java.lang.IllegalArgumentException: java.net.URISyntaxException: Relative path in absolute URI: jar:file:/home/vcap/app/BOOT-INF/lib/hive-exec-1.2.1.jar!

The path looks absolute to me. I'm not sure if the ! is part of the path (or error message) which may be upsetting it.

Any help would be greatly appreciated.

Cheers,

Theo

Cannot reliably get logs

I'm not sure if this is a cf issue, or a simple-hive issue. Please close if you suspect this a cf issue.

When running:

cf logs simple-hive-service

I do not get any [APP/x] output. However, as soon as I execute cf ssh simple-hive-service (which fails), then when I re-run:

cf logs simple-hive-service

I now have [APP/x] output.

Do you have any idea what could be causing this? I think the 2 commands are correlated as I have replicated it a couple of times after a re-stage, but it seems very strange.

Cheers,

Theo

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    ๐Ÿ–– Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. ๐Ÿ“Š๐Ÿ“ˆ๐ŸŽ‰

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google โค๏ธ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.