[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2019-02-21 Thread ASF subversion and git services (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16774606#comment-16774606
 ] 

ASF subversion and git services commented on IMPALA-7605:
-

Commit 4ed947365447934c55eeec94610a2b3cbd993937 in impala's branch 
refs/heads/master from Bharath Vissapragada
[ https://gitbox.apache.org/repos/asf?p=impala.git;h=4ed9473 ]

IMPALA-6900: Fix the min version invariant for invalidate metadata

Current flow of invalidate metadata is as follows.

1. Catalog server records the global catalog version *before* reset()
2. Catalog server invalidates all the metadata.
3. Catalog server returns the version recorded in step (1)
4. Coordinator should wait until the minimum version across all the
   local catalog objects is > the version returned in the step (3).

However, the invariant in step 4 on the coordinator side was incorrectly
coded resulting in an early termination of the wait loop.
This breaks the invalidate metadata contract and the subsequent queries
can fail while resolving catalog objects in the local cache.

Testing: I could reproduce this issue reliably on a pristine HMS with
high --statestore_update_frequency_ms (see IMPALA-7605 for details).
With the patch, I'm not able to reproduce it.

Change-Id: I22ace3f5917b6167af63c3dfd2620e69ce8ec1cb
Reviewed-on: http://gerrit.cloudera.org:8080/12547
Reviewed-by: Impala Public Jenkins 
Tested-by: Impala Public Jenkins 


> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
>  Labels: regression
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] A catalog update with 3 
> entries is assembled. Catalog version: 3 Last sent catalog version: 0
> I0921 10:28:53.571209 48924 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 3
> I0921 10:28:53.608983 48924 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-10-01 Thread bharath v (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16634210#comment-16634210
 ] 

bharath v commented on IMPALA-7605:
---

I think this is a dupe of IMPALA-6900. I could reliably repro the issue by 
increasing {{statestore_update_frequency_ms}} to {{1}} which increases the 
window of race. With the defaults, the race window is much smaller and that's 
the reason I was not hitting it locally.

> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
>  Labels: regression
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] A catalog update with 3 
> entries is assembled. Catalog version: 3 Last sent catalog version: 0
> I0921 10:28:53.571209 48924 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 3
> I0921 10:28:53.608983 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:53.609027 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:53.609058 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:53.609087 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:53.614903 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: foo1537550878
> I0921 10:28:53.614946 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: foo1537550878
> I0921 10:28:53.614977 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: foo1537550878
> I0921 10:28:53.615005 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: foo1537550878
> I0921 10:28:53.632726 48924 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:54.782857 48041 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-09-24 Thread Philip Zeyliger (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16626120#comment-16626120
 ] 

Philip Zeyliger commented on IMPALA-7605:
-

To belabor this: you're likely seeing a race. I wonder if CDH-73078 is similar. 
It was filed recently after https://review.infra.cloudera.com/r/97460/ added a 
sleep() somewhere.

> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
>  Labels: regression
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] A catalog update with 3 
> entries is assembled. Catalog version: 3 Last sent catalog version: 0
> I0921 10:28:53.571209 48924 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 3
> I0921 10:28:53.608983 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:53.609027 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:53.609058 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:53.609087 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:53.614903 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: foo1537550878
> I0921 10:28:53.614946 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: foo1537550878
> I0921 10:28:53.614977 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: foo1537550878
> I0921 10:28:53.615005 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: foo1537550878
> I0921 10:28:53.632726 48924 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:54.782857 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=5, original size=156
> 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-09-24 Thread Michael Brown (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16626027#comment-16626027
 ] 

Michael Brown commented on IMPALA-7605:
---

[~bharathv] It reproduces for me at hash 
083352b1e7e39e53d7146f37d206443057778653:

{noformat}
+ impala-shell.sh
Starting Impala Shell without Kerberos authentication
Connected to localhost:21000
Server version: impalad version 3.1.0-SNAPSHOT DEBUG (build 
083352b1e7e39e53d7146f37d206443057778653)
***
Welcome to the Impala shell.
(Impala Shell v3.1.0-SNAPSHOT (083352b) built on Mon Sep 24 08:24:06 PDT 2018)

After running a query, type SUMMARY to see a summary of where time was spent.
***
Query: invalidate metadata
Query submitted at: 2018-09-24 08:27:01 (Coordinator: http://mikeb-ub16:25000)
Query progress can be monitored at: 
http://mikeb-ub16:25000/query_plan?query_id=a4469b3d0bd93bc3:3a195423
Fetched 0 row(s) in 0.20s
Query: select * from foo1537802777.foo
Query submitted at: 2018-09-24 08:27:01 (Coordinator: http://mikeb-ub16:25000)
ERROR: AnalysisException: Could not resolve table reference: 'foo1537802777.foo'
{noformat}

I can tell you aren't actually running my reproduction script, because it uses 
a timestamp for a uniqueness factor.

One difference is that you are issuing commands one at a time at a shell 
prompt, and the script feeds lines to impala-shell's stdin. Maybe you should 
try feeding commands to impala-shell.sh's stdin like the script does, or just 
run the script completely as I've been doing.

> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
>  Labels: regression
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-09-21 Thread bharath v (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16624291#comment-16624291
 ] 

bharath v commented on IMPALA-7605:
---

No luck.

{noformat}
➜  Impala git:(imp7605) ✗ ./buildall.sh -notests -format
.. 
[50%] Building CXX object CMakeFiles/impalalzo.dir/hdfs-lzo-text-scanner.cc.o
[100%] Linking CXX shared library build/libimpalalzo.so
[100%] Built target impalalzo
[100%] Built target impala-lzo
Stopping Sentry
Stopping Hive
Stopping Hbase
Stopping kudu
Stopping kms
Stopping hdfs
The minikdc is not running.
Creating node-3 at /home/bharath/Impala/testdata/cluster/cdh6/node-3
node-3 will use ports DATANODE_PORT=31000, DATANODE_HTTP_PORT=31010, 
DATANODE_IPC_PORT=31020, DATANODE_HTTPS_PORT=31030, NODEMANAGER_PORT=31100, 
NODEMANAGER_LOCALIZER_PORT=31120, NODEMANAGER_WEBUI_PORT=31140, 
KUDU_TS_RPC_PORT=31200, and KUDU_TS_WEBUI_PORT=31300
Creating node-2 at /home/bharath/Impala/testdata/cluster/cdh6/node-2
node-2 will use ports DATANODE_PORT=31001, DATANODE_HTTP_PORT=31011, 
DATANODE_IPC_PORT=31021, DATANODE_HTTPS_PORT=31031, NODEMANAGER_PORT=31101, 
NODEMANAGER_LOCALIZER_PORT=31121, NODEMANAGER_WEBUI_PORT=31141, 
KUDU_TS_RPC_PORT=31201, and KUDU_TS_WEBUI_PORT=31301
Creating node-1 at /home/bharath/Impala/testdata/cluster/cdh6/node-1
node-1 will use ports DATANODE_PORT=31002, DATANODE_HTTP_PORT=31012, 
DATANODE_IPC_PORT=31022, DATANODE_HTTPS_PORT=31032, NODEMANAGER_PORT=31102, 
NODEMANAGER_LOCALIZER_PORT=31122, NODEMANAGER_WEBUI_PORT=31142, 
KUDU_TS_RPC_PORT=31202, and KUDU_TS_WEBUI_PORT=31302
Config dir: /home/bharath/Impala/fe/src/test/resources
Current user: bharath
Metastore DB: hive_impala_imp_7605
~/Impala/fe/src/test/resources ~/Impala
Creating postgresql database for Hive metastore
~/Impala/toolchain/cdh_components-559250/hive-2.1.1-cdh6.x-SNAPSHOT/scripts/metastore/upgrade/postgres
 ~/Impala/fe/src/test/resources ~/Impala
psql:hive-schema-2.1.1.postgres.sql:1462: WARNING:  no privileges could be 
revoked for "public"
psql:hive-schema-2.1.1.postgres.sql:1463: WARNING:  no privileges were granted 
for "public"
~/Impala/fe/src/test/resources ~/Impala
Creating Sentry Policy Server DB
Linking core-site.xml from local cluster
Linking hdfs-site.xml from local cluster

➜  Impala git:(imp7605) ✗ hive
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in 
[jar:file:/home/bharath/Impala/toolchain/cdh_components-559250/hive-2.1.1-cdh6.x-SNAPSHOT/lib/log4j-slf4j-impl-2.8.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in 
[jar:file:/home/bharath/Impala/toolchain/cdh_components-559250/hadoop-3.0.0-cdh6.x-SNAPSHOT/share/hadoop/common/lib/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]

Logging initialized using configuration in 
file:/home/bharath/Impala/fe/src/test/resources/hive-log4j2.properties Async: 
false

WARNING: Hive CLI is deprecated and migration to Beeline is recommended.
hive> create database foo;
OK
Time taken: 1.304 seconds
hive> use foo;
OK
Time taken: 0.034 seconds
hive> create table test(a int);
OK
Time taken: 0.694 seconds
hive> insert into test values (1);
Query ID = bharath_2018092119_fc517153-a54b-4fc1-a9d8-66b8cffb6e22
Total jobs = 3
Launching Job 1 out of 3
Number of reduce tasks is set to 0 since there's no reduce operator
18/09/21 15:56:01 INFO lzo.GPLNativeCodeLoader: Loaded native gpl library
18/09/21 15:56:01 INFO lzo.LzoCodec: Successfully loaded & initialized 
native-lzo library [hadoop-lzo rev d5ed4529bd7dc713375eff15f516fcfa1d20090b]
18/09/21 15:56:01 INFO mapred.LocalDistributedCacheManager: Creating symlink: 
/tmp/hadoop-bharath/mapred/local/1537570561408/libjars <- 
/home/bharath/Impala/libjars/*
18/09/21 15:56:01 WARN mapred.LocalDistributedCacheManager: Failed to create 
symlink: /tmp/hadoop-bharath/mapred/local/1537570561408/libjars <- 
/home/bharath/Impala/libjars/*
18/09/21 15:56:01 INFO mapred.LocalDistributedCacheManager: Localized 
file:/tmp/hadoop/mapred/staging/bharath839177781/.staging/job_local839177781_0001/libjars
 as file:/tmp/hadoop-bharath/mapred/local/1537570561408/libjars
Job running in-process (local Hadoop)
18/09/21 15:56:01 INFO mapred.LocalJobRunner: OutputCommitter set in config 
org.apache.hadoop.hive.ql.io.HiveFileFormatUtils$NullOutputCommitter
18/09/21 15:56:01 INFO mapred.LocalJobRunner: OutputCommitter is 
org.apache.hadoop.hive.ql.io.HiveFileFormatUtils$NullOutputCommitter
18/09/21 15:56:01 INFO mapred.LocalJobRunner: Waiting for map tasks
18/09/21 15:56:01 INFO mapred.LocalJobRunner: Starting task: 
attempt_local839177781_0001_m_00_0
18/09/21 15:56:01 INFO mapred.LocalJobRunner: 
18/09/21 15:56:01 INFO mapred.LocalJobRunner: 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-09-21 Thread Michael Brown (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16624214#comment-16624214
 ] 

Michael Brown commented on IMPALA-7605:
---

I've been able to, yes. I also had done a ./buildall.sh -notests -format 
initially as a harder, more drastic way of resetting. Maybe you need to do that 
as well?

> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
>  Labels: regression
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] A catalog update with 3 
> entries is assembled. Catalog version: 3 Last sent catalog version: 0
> I0921 10:28:53.571209 48924 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 3
> I0921 10:28:53.608983 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:53.609027 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:53.609058 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:53.609087 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:53.614903 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: foo1537550878
> I0921 10:28:53.614946 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: foo1537550878
> I0921 10:28:53.614977 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: foo1537550878
> I0921 10:28:53.615005 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: foo1537550878
> I0921 10:28:53.632726 48924 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:54.782857 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=5, original size=156
> I0921 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-09-21 Thread bharath v (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16624210#comment-16624210
 ] 

bharath v commented on IMPALA-7605:
---

Thanks Michael for the detailed steps. I tried a couple of times from a clean 
HMS, not able to reproduce it. Maybe I'm doing something wrong. Are you able to 
repro it on demand?

> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
>  Labels: regression
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] A catalog update with 3 
> entries is assembled. Catalog version: 3 Last sent catalog version: 0
> I0921 10:28:53.571209 48924 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 3
> I0921 10:28:53.608983 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:53.609027 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:53.609058 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:53.609087 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:53.614903 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: foo1537550878
> I0921 10:28:53.614946 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: foo1537550878
> I0921 10:28:53.614977 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: foo1537550878
> I0921 10:28:53.615005 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: foo1537550878
> I0921 10:28:53.632726 48924 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:54.782857 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=5, original size=156
> I0921 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-09-21 Thread Michael Brown (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16624026#comment-16624026
 ] 

Michael Brown commented on IMPALA-7605:
---

bq. Upon the first access, AnalysisException is raised.

What I mean here is, when impala tries to select from the table created in hive.

> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] A catalog update with 3 
> entries is assembled. Catalog version: 3 Last sent catalog version: 0
> I0921 10:28:53.571209 48924 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 3
> I0921 10:28:53.608983 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:53.609027 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:53.609058 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:53.609087 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:53.614903 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: foo1537550878
> I0921 10:28:53.614946 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: foo1537550878
> I0921 10:28:53.614977 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: foo1537550878
> I0921 10:28:53.615005 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: foo1537550878
> I0921 10:28:53.632726 48924 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:54.782857 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=5, original size=156
> I0921 10:28:54.782948 48041 catalog-server.cc:490] Collected update: 
> 

[jira] [Commented] (IMPALA-7605) AnalysisException when first accessing Hive-create table on pristine HMS

2018-09-21 Thread Michael Brown (JIRA)


[ 
https://issues.apache.org/jira/browse/IMPALA-7605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16624016#comment-16624016
 ] 

Michael Brown commented on IMPALA-7605:
---

[~bharathv] I've attached 3.0 vs. 3.1 logs, and the reproduction script.

> AnalysisException when first accessing Hive-create table on pristine HMS
> 
>
> Key: IMPALA-7605
> URL: https://issues.apache.org/jira/browse/IMPALA-7605
> Project: IMPALA
>  Issue Type: Bug
>  Components: Catalog
>Affects Versions: Impala 3.1.0
>Reporter: Michael Brown
>Assignee: bharath v
>Priority: Blocker
> Attachments: 3.0-logs.tar.gz, 3.1-logs.tar.gz, metadata-bug.sh
>
>
> This is a corner case encountered when loading test data from Hive on a 
> pristine/new cluster. As we tend to keep bigger clusters around and upgrade 
> them, as opposed to refreshing them, and our data load doesn't hit this 
> either, this was tough to spot.
> The procedure in general is to start with a pristine HMS, create a table in 
> Hive, and use Impala to access the table. Upon the first access, 
> AnalysisException is raised. Subsequent accesses work.
> This is a P1 in the sense that, while a user can try again and succeed, test 
> automation is going to increasingly load data via Hive and then access it in 
> Impala. This case needs to work. The other thing making this a P1 is that 
> it's a change behavior relative to both 2.12 and 3.0 and thus a regression.
> Here's what catalogd.INFO looks like in the successful case (3.0):
> {noformat}
> I0921 10:28:23.697592 47879 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 0
> I0921 10:28:23.810739 47879 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:23.811686 47879 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:23.811738 47879 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:23.811772 47879 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:23.853292 47879 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:23.860013 47879 statestore-subscriber.cc:190] Starting statestore 
> subscriber
> I0921 10:28:23.861377 47879 thrift-server.cc:452] ThriftServer 
> 'StatestoreSubscriber' started on port: 23020
> I0921 10:28:23.861383 47879 statestore-subscriber.cc:217] Registering with 
> statestore
> I0921 10:28:23.861979 47879 statestore-subscriber.cc:174] Subscriber 
> registration ID: 624d03c923c15c12:f9204d9fb14054a9
> I0921 10:28:23.861989 47879 statestore-subscriber.cc:221] statestore 
> registration successful
> I0921 10:28:23.868679 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=2, original size=156
> I0921 10:28:23.870929 48041 catalog-server.cc:490] Collected deletion: 
> DATABASE:_impala_builtins, version=3, original size=140
> I0921 10:28:23.872802 48041 catalog-server.cc:490] Collected update: 
> CATALOG_SERVICE_ID, version=3, original size=49
> I0921 10:28:23.875424 47879 thrift-server.cc:452] ThriftServer 
> 'CatalogService' started on port: 26000
> I0921 10:28:23.875434 47879 catalogd-main.cc:111] CatalogService started on 
> port: 26000
> I0921 10:28:26.776692 48047 catalog-server.cc:245] A catalog update with 3 
> entries is assembled. Catalog version: 3 Last sent catalog version: 0
> I0921 10:28:53.571209 48924 CatalogServiceCatalog.java:1102] Invalidating all 
> metadata. Version: 3
> I0921 10:28:53.608983 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: default
> I0921 10:28:53.609027 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: default
> I0921 10:28:53.609058 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: default
> I0921 10:28:53.609087 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: default
> I0921 10:28:53.614903 48924 CatalogServiceCatalog.java:914] Loading native 
> functions for database: foo1537550878
> I0921 10:28:53.614946 48924 CatalogServiceCatalog.java:930] Loaded native 
> functions for database: foo1537550878
> I0921 10:28:53.614977 48924 CatalogServiceCatalog.java:941] Loading Java 
> functions for database: foo1537550878
> I0921 10:28:53.615005 48924 CatalogServiceCatalog.java:952] Loaded Java 
> functions for database: foo1537550878
> I0921 10:28:53.632726 48924 CatalogServiceCatalog.java:1170] Invalidated all 
> metadata.
> I0921 10:28:54.782857 48041 catalog-server.cc:490] Collected update: 
> DATABASE:default, version=5, original size=156
> I0921 10:28:54.782948 48041 catalog-server.cc:490] Collected update: 
> DATABASE:foo1537550878, version=6, original size=156
> I0921