Presto: DROP TABLE not deleting data from S3

Created on 27 Jun 2019  路  16Comments  路  Source: prestosql/presto

Hi,

We're having an issue dropping tables that are created, then have data inserted via INSERT INTO.

Example:

create table example.table (id varchar(25));
insert into table example.table values ('1');
drop table example.table;

The table is deleted from hive metastore, but not from the S3 bucket. If we try to re-create the table, there is an error saying that the table location already exists

This does not happen if the table is created with: CREATE TABLE AS ... SELECT

picture rmgpinto

Most helpful comment

For anyone that reaches the same issue: hive.metastore.thrift.delete-files-on-drop=true

picture rmgpinto on 15 Nov 2020
👍2

All 16 comments

Since the table was created as managed (not "external") table, the Metastore is supposed to delete the data upon DROP TABLE.
However, most likely it didn't have the necessary privileges. Can you check the metastore log output for any related messages?

findepi picture findepi on 27 Jun 2019

To expand on @findepi's answer, in the Hive model, deleting data for a partition or table is the metastore's responsibility. The drop_table() call on the metastore has a deleteData flag which Presto sets to true. Presto never deletes the data itself.

electrum picture electrum on 27 Jun 2019

The permissions are correctly set because the table can be dropped if it's created with a CREATE TABLE ... AS SELECT ....

I'll restart the metastore with debug to check what's happening as @findepi suggested.

rmgpinto picture rmgpinto on 28 Jun 2019

@rmgpinto what does the metastore log say?

findepi picture findepi on 28 Jun 2019

@findepi I've isolated the log of the drop statement, please find it below.
I can't find anything wrong with it.

2019-06-30T22:21:57,750 DEBUG [pool-6-thread-199] metrics.PerfLogger: <PERFLOG method=get_table from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2019-06-30T22:21:57,750  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: source:10.2.30.92 get_table : tbl=hive.example.table1
2019-06-30T22:21:57,750  INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=hive-metastore   ip=10.2.30.92   cmd=source:10.2.30.92 get_table : tbl=hive.example.table1   
2019-06-30T22:21:57,751  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: Opening raw store with implementation class:org.apache.hadoop.hive.metastore.ObjectStore
2019-06-30T22:21:57,751  WARN [pool-6-thread-199] metastore.ObjectStore: datanucleus.autoStartMechanismMode is set to unsupported value null . Setting it to value: ignored
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.autoCreateAll value null from jpox.properties with false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionDriverName value null from jpox.properties with org.postgresql.Driver
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPool.maxPoolSize value null from jpox.properties with 10
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPoolingType value null from jpox.properties with HikariCP
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionURL value null from jpox.properties with jdbc:postgresql://hive-metastore-database.presto-production.svc.cluster.local/metastore
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionUserName value null from jpox.properties with postgres
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.autoStartMechanismMode value null from jpox.properties with ignored
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2 value null from jpox.properties with false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2.type value null from jpox.properties with none
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.initializeColumnInfo value null from jpox.properties with NONE
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.plugin.pluginRegistryBundleCheck value null from jpox.properties with LOG
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.transactionIsolation value null from jpox.properties with read-committed
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.useLegacyNativeValueStrategy value null from jpox.properties with true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.DetachAllOnCommit value null from jpox.properties with true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.identifierFactory value null from jpox.properties with datanucleus1
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.PersistenceManagerFactoryClass value null from jpox.properties with org.datanucleus.api.jdo.JDOPersistenceManagerFactory
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.Multithreaded value null from jpox.properties with true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.NonTransactionalRead value null from jpox.properties with true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.storeManagerType value null from jpox.properties with rdbms
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateColumns value null from jpox.properties with false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateConstraints value null from jpox.properties with false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateTables value null from jpox.properties with false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.autoCreateAll = false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateTables = false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.useLegacyNativeValueStrategy = true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateColumns = false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPool.maxPoolSize = 10
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.autoStartMechanismMode = ignored
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.initializeColumnInfo = NONE
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.Multithreaded = true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.identifierFactory = datanucleus1
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.transactionIsolation = read-committed
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionURL = jdbc:postgresql://hive-metastore-database.presto-production.svc.cluster.local/metastore
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.DetachAllOnCommit = true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.NonTransactionalRead = true
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateConstraints = false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionDriverName = org.postgresql.Driver
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionUserName = postgres
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2 = false
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.plugin.pluginRegistryBundleCheck = LOG
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2.type = none
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.PersistenceManagerFactoryClass = org.datanucleus.api.jdo.JDOPersistenceManagerFactory
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.storeManagerType = rdbms
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPoolingType = HikariCP
2019-06-30T22:21:57,751 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@80ab3a4, with PersistenceManager: null will be shutdown
2019-06-30T22:21:57,751  INFO [pool-6-thread-199] metastore.ObjectStore: ObjectStore, initialize called
2019-06-30T22:21:57,752 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@d492eca
2019-06-30T22:21:57,753 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@d492eca
2019-06-30T22:21:57,754 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@d492eca
2019-06-30T22:21:57,764 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@125ba879
2019-06-30T22:21:57,764  INFO [pool-6-thread-199] metastore.MetaStoreDirectSql: Using direct SQL, underlying DB is POSTGRES
2019-06-30T22:21:57,764 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@80ab3a4, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@f8f5b02 created in the thread with id: 222
2019-06-30T22:21:57,764  INFO [pool-6-thread-199] metastore.ObjectStore: Initialized ObjectStore
2019-06-30T22:21:57,764 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 1, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1506)
    sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,764 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1852)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1507)
2019-06-30T22:21:57,764 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing getMTable for hive.example.table1
2019-06-30T22:21:57,770 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1871)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1507)
2019-06-30T22:21:57,784 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 0, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1513)
    sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,785 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@125ba879
2019-06-30T22:21:57,785 DEBUG [pool-6-thread-199] metrics.PerfLogger: </PERFLOG method=get_table start=1561929717750 end=1561929717785 duration=35 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=199 retryCount=0 error=false>
2019-06-30T22:21:57,786  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: Cleaning up thread local RawStore...
2019-06-30T22:21:57,786  INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=hive-metastore   ip=10.2.30.92   cmd=Cleaning up thread local RawStore...    
2019-06-30T22:21:57,786 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@80ab3a4, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@f8f5b02 will be shutdown
2019-06-30T22:21:57,786  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: Done cleaning up thread local RawStore
2019-06-30T22:21:57,786  INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=hive-metastore   ip=10.2.30.92   cmd=Done cleaning up thread local RawStore  
2019-06-30T22:21:57,787 DEBUG [pool-6-thread-199] metrics.PerfLogger: <PERFLOG method=drop_table from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2019-06-30T22:21:57,787  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: source:10.2.30.92 drop_table : tbl=hive.example.table1
2019-06-30T22:21:57,787  INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=hive-metastore   ip=10.2.30.92   cmd=source:10.2.30.92 drop_table : tbl=hive.example.table1  
2019-06-30T22:21:57,788  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: Opening raw store with implementation class:org.apache.hadoop.hive.metastore.ObjectStore
2019-06-30T22:21:57,788  WARN [pool-6-thread-199] metastore.ObjectStore: datanucleus.autoStartMechanismMode is set to unsupported value null . Setting it to value: ignored
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.autoCreateAll value null from jpox.properties with false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionDriverName value null from jpox.properties with org.postgresql.Driver
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPool.maxPoolSize value null from jpox.properties with 10
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPoolingType value null from jpox.properties with HikariCP
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionURL value null from jpox.properties with jdbc:postgresql://hive-metastore-database.presto-production.svc.cluster.local/metastore
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionUserName value null from jpox.properties with postgres
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.autoStartMechanismMode value null from jpox.properties with ignored
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2 value null from jpox.properties with false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2.type value null from jpox.properties with none
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.initializeColumnInfo value null from jpox.properties with NONE
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.plugin.pluginRegistryBundleCheck value null from jpox.properties with LOG
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.transactionIsolation value null from jpox.properties with read-committed
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.useLegacyNativeValueStrategy value null from jpox.properties with true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.DetachAllOnCommit value null from jpox.properties with true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.identifierFactory value null from jpox.properties with datanucleus1
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.PersistenceManagerFactoryClass value null from jpox.properties with org.datanucleus.api.jdo.JDOPersistenceManagerFactory
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.Multithreaded value null from jpox.properties with true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.NonTransactionalRead value null from jpox.properties with true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.storeManagerType value null from jpox.properties with rdbms
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateColumns value null from jpox.properties with false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateConstraints value null from jpox.properties with false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateTables value null from jpox.properties with false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.autoCreateAll = false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateTables = false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.useLegacyNativeValueStrategy = true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateColumns = false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPool.maxPoolSize = 10
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.autoStartMechanismMode = ignored
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.initializeColumnInfo = NONE
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.Multithreaded = true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.identifierFactory = datanucleus1
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.transactionIsolation = read-committed
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionURL = jdbc:postgresql://hive-metastore-database.presto-production.svc.cluster.local/metastore
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.DetachAllOnCommit = true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.NonTransactionalRead = true
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateConstraints = false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionDriverName = org.postgresql.Driver
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionUserName = postgres
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2 = false
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.plugin.pluginRegistryBundleCheck = LOG
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2.type = none
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.PersistenceManagerFactoryClass = org.datanucleus.api.jdo.JDOPersistenceManagerFactory
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.storeManagerType = rdbms
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPoolingType = HikariCP
2019-06-30T22:21:57,788 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@816226b, with PersistenceManager: null will be shutdown
2019-06-30T22:21:57,788  INFO [pool-6-thread-199] metastore.ObjectStore: ObjectStore, initialize called
2019-06-30T22:21:57,789 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@d492eca
2019-06-30T22:21:57,789 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@d492eca
2019-06-30T22:21:57,790 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@d492eca
2019-06-30T22:21:57,792 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@125ba879
2019-06-30T22:21:57,792  INFO [pool-6-thread-199] metastore.MetaStoreDirectSql: Using direct SQL, underlying DB is POSTGRES
2019-06-30T22:21:57,792 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@816226b, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@568d123c created in the thread with id: 222
2019-06-30T22:21:57,792  INFO [pool-6-thread-199] metastore.ObjectStore: Initialized ObjectStore
2019-06-30T22:21:57,792 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 1, isActive = true  at:
    sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    java.lang.reflect.Method.invoke(Method.java:498)
2019-06-30T22:21:57,792 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.start(ObjectStore.java:3603)
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:3573)
    org.apache.hadoop.hive.metastore.ObjectStore.getDatabaseInternal(ObjectStore.java:1018)
2019-06-30T22:21:57,794 DEBUG [pool-6-thread-199] metastore.MetaStoreDirectSql: getDatabase: directsql returning db example locn[s3a://data-lake-test-bucket/example] desc [null] owner [hive-metastore] ownertype [USER]
2019-06-30T22:21:57,794 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.commit(ObjectStore.java:3691)
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:3588)
    org.apache.hadoop.hive.metastore.ObjectStore.getDatabaseInternal(ObjectStore.java:1018)
2019-06-30T22:21:57,794 DEBUG [pool-6-thread-199] metastore.ObjectStore: db details for db example retrieved using SQL in 2.115479ms
2019-06-30T22:21:57,794 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1506)
    sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,794 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1852)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1507)
2019-06-30T22:21:57,795 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing getMTable for hive.example.table1
2019-06-30T22:21:57,797 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1871)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1507)
2019-06-30T22:21:57,807 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1513)
    sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,807 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1506)
    sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,807 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1852)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1507)
2019-06-30T22:21:57,807 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing getMTable for hive.example.table1
2019-06-30T22:21:57,808 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1871)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1507)
2019-06-30T22:21:57,808 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:1513)
    sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,808 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.start(ObjectStore.java:3603)
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:3573)
    org.apache.hadoop.hive.metastore.ObjectStore.getPartitionsInternal(ObjectStore.java:2745)
2019-06-30T22:21:57,833 DEBUG [pool-6-thread-199] metastore.MetaStoreDirectSql: Direct SQL query in 24.623706ms + 0.008856ms, the query is [select "PARTITIONS"."PART_ID" from "PARTITIONS"  inner join "TBLS" on "PARTITIONS"."TBL_ID" = "TBLS"."TBL_ID"     and "TBLS"."TBL_NAME" = ?   inner join "DBS" on "TBLS"."DB_ID" = "DBS"."DB_ID"      and "DBS"."NAME" = ?  where "DBS"."CTLG_NAME" = ?  order by "PART_NAME" asc]
2019-06-30T22:21:57,833 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.commit(ObjectStore.java:3691)
    org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:3588)
    org.apache.hadoop.hive.metastore.ObjectStore.getPartitionsInternal(ObjectStore.java:2745)
2019-06-30T22:21:57,833 DEBUG [pool-6-thread-199] metastore.ObjectStore: 0 entries retrieved using SQL in 24.890134ms
2019-06-30T22:21:57,833 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.dropConstraint(ObjectStore.java:10319)
    sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,843 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.dropConstraint(ObjectStore.java:10329)
    sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,843 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1373)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,843 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1852)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1374)
2019-06-30T22:21:57,843 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing getMTable for hive.example.table1
2019-06-30T22:21:57,844 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1871)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1374)
2019-06-30T22:21:57,844 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing listAllTableGrants
2019-06-30T22:21:57,844 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listAllTableGrants(ObjectStore.java:6546)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1379)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,853 DEBUG [pool-6-thread-199] metastore.ObjectStore: Done executing query for listAllTableGrants
2019-06-30T22:21:57,856 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listAllTableGrants(ObjectStore.java:6555)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1379)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,856 DEBUG [pool-6-thread-199] metastore.ObjectStore: Done retrieving all objects for listAllTableGrants
2019-06-30T22:21:57,860 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing listTableAllColumnGrants
2019-06-30T22:21:57,860 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllColumnGrants(ObjectStore.java:6613)
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllColumnGrants(ObjectStore.java:6598)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1383)
2019-06-30T22:21:57,871 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllColumnGrants(ObjectStore.java:6630)
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllColumnGrants(ObjectStore.java:6598)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1383)
2019-06-30T22:21:57,871 DEBUG [pool-6-thread-199] metastore.ObjectStore: Done retrieving all objects for listTableAllColumnGrants
2019-06-30T22:21:57,871 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing listTableAllPartitionGrants
2019-06-30T22:21:57,871 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllPartitionGrants(ObjectStore.java:6577)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1389)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,881 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllPartitionGrants(ObjectStore.java:6585)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1389)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,881 DEBUG [pool-6-thread-199] metastore.ObjectStore: Done retrieving all objects for listTableAllPartitionGrants
2019-06-30T22:21:57,881 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing listTableAllPartitionColumnGrants
2019-06-30T22:21:57,881 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllPartitionColumnGrants(ObjectStore.java:6653)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1394)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,891 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.listTableAllPartitionColumnGrants(ObjectStore.java:6661)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1394)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,891 DEBUG [pool-6-thread-199] metastore.ObjectStore: Done retrieving all objects for listTableAllPartitionColumnGrants
2019-06-30T22:21:57,891 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.deleteTableColumnStatistics(ObjectStore.java:8738)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1401)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,891 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 4, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1852)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.deleteTableColumnStatistics(ObjectStore.java:8739)
2019-06-30T22:21:57,891 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing getMTable for hive.example.table1
2019-06-30T22:21:57,892 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 3, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1871)
    org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:1899)
    org.apache.hadoop.hive.metastore.ObjectStore.deleteTableColumnStatistics(ObjectStore.java:8739)
2019-06-30T22:21:57,893 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.deleteTableColumnStatistics(ObjectStore.java:8789)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1401)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
2019-06-30T22:21:57,895 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.removeUnusedColumnDescriptor(ObjectStore.java:4232)
    org.apache.hadoop.hive.metastore.ObjectStore.preDropStorageDescriptor(ObjectStore.java:4268)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1413)
2019-06-30T22:21:57,895 DEBUG [pool-6-thread-199] metastore.ObjectStore: execute removeUnusedColumnDescriptor
2019-06-30T22:21:57,903 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.removeUnusedColumnDescriptor(ObjectStore.java:4245)
    org.apache.hadoop.hive.metastore.ObjectStore.preDropStorageDescriptor(ObjectStore.java:4268)
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1413)
2019-06-30T22:21:57,903 DEBUG [pool-6-thread-199] metastore.ObjectStore: successfully deleted a CD in removeUnusedColumnDescriptor
2019-06-30T22:21:57,985 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true  at:
    org.apache.hadoop.hive.metastore.ObjectStore.dropTable(ObjectStore.java:1423)
    sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2019-06-30T22:21:57,985 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 0, isactive true  at:
    sun.reflect.GeneratedMethodAccessor33.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    java.lang.reflect.Method.invoke(Method.java:498)
2019-06-30T22:21:58,000 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@125ba879
2019-06-30T22:21:58,000 DEBUG [pool-6-thread-199] metastore.ReplChangeManager: Repl policy is not set for database 
2019-06-30T22:21:58,000 DEBUG [pool-6-thread-199] utils.FileUtils: deleting  s3a://data-lake-test-bucket/example/table1
2019-06-30T22:21:58,000 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: op_get_file_status += 1  ->  718
2019-06-30T22:21:58,000 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting path status for s3a://data-lake-test-bucket/example/table1  (example/table1)
2019-06-30T22:21:58,000 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2099
2019-06-30T22:21:58,055 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2100
2019-06-30T22:21:58,065 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found file (with /): fake directory
2019-06-30T22:21:58,065 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: op_delete += 1  ->  333
2019-06-30T22:21:58,065 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: op_get_file_status += 1  ->  719
2019-06-30T22:21:58,065 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting path status for s3a://data-lake-test-bucket/example/table1  (example/table1)
2019-06-30T22:21:58,065 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2101
2019-06-30T22:21:58,072 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2102
2019-06-30T22:21:58,080 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found file (with /): fake directory
2019-06-30T22:21:58,081 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Delete path s3a://data-lake-test-bucket/example/table1 - recursive true
2019-06-30T22:21:58,081 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: delete: Path is a directory: s3a://data-lake-test-bucket/example/table1
2019-06-30T22:21:58,081 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Deleting fake empty directory example/table1/
2019-06-30T22:21:58,081 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_delete_requests += 1  ->  342
2019-06-30T22:21:58,092 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2103
2019-06-30T22:21:58,097 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2104
2019-06-30T22:21:58,103 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_list_requests += 1  ->  1345
2019-06-30T22:21:58,118 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found path as directory (with /): 1/0
2019-06-30T22:21:58,118 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Prefix: example/table2/
2019-06-30T22:21:58,118 DEBUG [pool-6-thread-199] metrics.PerfLogger: </PERFLOG method=drop_table start=1561929717787 end=1561929718118 duration=331 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=199 retryCount=0 error=false>
2019-06-30T22:21:58,118  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: Cleaning up thread local RawStore...
2019-06-30T22:21:58,118  INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=hive-metastore   ip=10.2.30.92   cmd=Cleaning up thread local RawStore...    
2019-06-30T22:21:58,118 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@816226b, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@568d123c will be shutdown
2019-06-30T22:21:58,118  INFO [pool-6-thread-199] metastore.HiveMetaStore: 199: Done cleaning up thread local RawStore
2019-06-30T22:21:58,118  INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=hive-metastore   ip=10.2.30.92   cmd=Done cleaning up thread local RawStore
rmgpinto picture rmgpinto on 30 Jun 2019

If I drop the table (but create it with CREATE TABLE example.table1 AS SELECT 1 AS id, the metastore can delete the S3 folder properly.
Line 8 highlights the S3 file that contains the table data to be deleted (that's the difference I noticed comparing to the log above).

2019-06-30T22:26:22,878 DEBUG [pool-6-thread-199] utils.FileUtils: deleting  s3a://data-lake-test-bucket/example/table1
2019-06-30T22:26:22,878 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: op_get_file_status += 1  ->  732
2019-06-30T22:26:22,878 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting path status for s3a://data-lake-test-bucket/example/table1  (example/table1)
2019-06-30T22:26:22,878 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2131
2019-06-30T22:26:22,897 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2132
2019-06-30T22:26:22,903 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_list_requests += 1  ->  1364
2019-06-30T22:26:22,917 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found path as directory (with /): 0/1
2019-06-30T22:26:22,917 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Summary: example/table1/20190630_212615_23867_vmwf3_1c4215b6-8d60-4fb3-948c-267e930c19c2 272
2019-06-30T22:26:22,917 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: op_delete += 1  ->  335
2019-06-30T22:26:22,917 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: op_get_file_status += 1  ->  733
2019-06-30T22:26:22,917 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting path status for s3a://data-lake-test-bucket/example/table1  (example/table1)
2019-06-30T22:26:22,917 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2133
2019-06-30T22:26:22,923 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2134
2019-06-30T22:26:22,927 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_list_requests += 1  ->  1365
2019-06-30T22:26:22,940 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found path as directory (with /): 0/1
2019-06-30T22:26:22,940 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Summary: example/table1/20190630_212615_23867_vmwf3_1c4215b6-8d60-4fb3-948c-267e930c19c2 272
2019-06-30T22:26:22,940 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Delete path s3a://data-lake-test-bucket/example/table1 - recursive true
2019-06-30T22:26:22,940 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: delete: Path is a directory: s3a://data-lake-test-bucket/example/table1
2019-06-30T22:26:22,940 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting objects for directory prefix example/table1/ to delete
2019-06-30T22:26:22,940 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_list_requests += 1  ->  1366
2019-06-30T22:26:22,954 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Got object to delete example/table1/20190630_212615_23867_vmwf3_1c4215b6-8d60-4fb3-948c-267e930c19c2
2019-06-30T22:26:22,954 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_delete_requests += 1  ->  344
2019-06-30T22:26:22,973 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2135
2019-06-30T22:26:23,000 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2136
2019-06-30T22:26:23,005 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_list_requests += 1  ->  1367
rmgpinto picture rmgpinto on 30 Jun 2019

From the first log:

2019-06-30T22:21:58,000 DEBUG [pool-6-thread-199] utils.FileUtils: deleting  s3a://data-lake-test-bucket/example/table1
...
2019-06-30T22:21:58,065 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting path status for s3a://data-lake-test-bucket/example/table1  (example/table1)
2019-06-30T22:21:58,065 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2101
2019-06-30T22:21:58,072 DEBUG [pool-6-thread-199] s3a.S3AStorageStatistics: object_metadata_requests += 1  ->  2102
2019-06-30T22:21:58,080 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found file (with /): fake directory
2019-06-30T22:21:58,081 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Delete path s3a://data-lake-test-bucket/example/table1 - recursive true
2019-06-30T22:21:58,081 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: delete: Path is a directory: s3a://data-lake-test-bucket/example/table1
2019-06-30T22:21:58,081 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Deleting fake empty directory example/table1/

It is apparent the Metastore attempts to delete data on S3.
It seems it doesn't see the data files to delete and leaves them behind
(the second log contains the name of data file being deleted).
I think this could be S3 consistency issue.

  • does it happen every time?
  • do you observer the same behavior when you do a long sleep between INSERT and DROP?
    For example you INSERT today and DROP tomorrow.
findepi picture findepi on 30 Jun 2019

It happens every time.

I'll execute the INSERT today, and leave the DROP for tomorrow, I'll post the results as soon as I get them.

Thank you for your help

rmgpinto picture rmgpinto on 30 Jun 2019

Same behaviour.

I'm running prestosql 314.

rmgpinto picture rmgpinto on 1 Jul 2019

I played with it for a while and found interesting findings.

image

In Presto:

create table temp.test_s3_drop_issue (x int);
insert into temp.test_s3_drop_issue values (10), (20);
insert into temp.test_s3_drop_issue values (30), (40);

image

Test1: 

Configuration conf = new Configuration();
conf.set(S3FileSystem.S3_ACCESS_KEY,"my_access_key");
conf.set(S3FileSystem.S3_SECRET_KEY,"my_secret_key");
S3FileSystem fs = new S3FileSystem();
fs.initialize(new java.net.URI("s3://presto-db/"), conf);
fs.delete(new org.apache.hadoop.fs.Path("s3://presto-db/temp/test_s3_drop_issue/"), true);

Results for Test1: Nothing was deleted.

Test2: (Same but Path is constructed from URI)

Configuration conf = new Configuration();
conf.set(S3FileSystem.S3_ACCESS_KEY,"my_access_key");
conf.set(S3FileSystem.S3_SECRET_KEY,"my_secret_key");
S3FileSystem fs = new S3FileSystem();
fs.initialize(new java.net.URI("s3://presto-db/"), conf);
fs.delete(new org.apache.hadoop.fs.Path(new java.net.URI("s3://presto-db/temp/test_s3_drop_issue/")), true);

Results for Test2: Files were deleted.

image

drop table temp.test_s3_drop_issue

image

Staring all again but this time after dropping the table:

create table temp.test_s3_drop_issue (x int);
insert into temp.test_s3_drop_issue values (10), (20);
insert into temp.test_s3_drop_issue values (30), (40);
drop table temp.test_s3_drop_issue;

image

Results for Test1: Files deleted.
image

Results for Test2: Nothing was deleted.

This time, files were deleted only in Test1 (with the Path that is constructed from String)

I have a feeling that that it somehow relates to this issue.
Will try to dig into it further.

guyco33 picture guyco33 on 1 Jul 2019

@guyco33 thank you for your investigation!

fs.delete(new org.apache.hadoop.fs.Path("s3://presto-db/test/test_s3_drop_issue/"), true);

Results for Test1: Nothing was deleted.

Is it presto-db/test or presto-db/temp?
Is it a typo when composing github comment or you actually tested with a wrong path?

Results for Test1: Nothing was deleted.

Test2: (Same but Path is constructed from URI)
...
fs.delete(new org.apache.hadoop.fs.Path(new java.net.URI("s3://presto-db/temp/test_s3_drop_issue/")), true);

Results for Test2: Files were deleted.

There is a difference in the trailing slash

System.out.println(new Path(        "s3://presto-db/temp/test_s3_drop_issue/"));   // s3://presto-db/temp/test_s3_drop_issue
System.out.println(new Path(new URI("s3://presto-db/temp/test_s3_drop_issue/")));  // s3://presto-db/temp/test_s3_drop_issue/

I think Hive metastore code uses Path(String) constructor:
https://github.com/apache/hive/blob/9fb2238fac7707b2fbb3a33066d1f9cc077904f3/metastore/src/java/org/apache/hadoop/hive/metastore/HiveMetaStore.java#L1685

findepi picture findepi on 3 Jul 2019
👍1

fs.delete(new org.apache.hadoop.fs.Path("s3://presto-db/test/test_s3_drop_issue/"), true);
Results for Test1: Nothing was deleted.

Is it presto-db/test or presto-db/temp?
Is it a typo when composing github comment or you actually tested with a wrong path?

Yes. It's a typo. Thanks @findepi for catching it !

guyco33 picture guyco33 on 4 Jul 2019

The hidden 0 "file" (that is created after creating an empty table) is AWS implementation for Folders (https://docs.aws.amazon.com/AmazonS3/latest/user-guide/create-folder.html)
I checked the content type of this hidden 0 "file":

Test1 - Folder (test_s3_drop_issue/) created by AWS console:
ObjectMetadata objectMetadata1 = fs.s3.getObjectMetadata("presto-db","temp/test_s3_drop_issue/");
System.out.println(objectMetadata1.getContentType());
Results with: application/x-directory

Test2 - Folder (test_s3_drop_issue/) created by ThriftHiveMetastore empty Presto table:
Running the same code results with:
application/octet-stream

Maybe the all issue is because the Folder (hidden 0 "file") is not created properly by ThriftHiveMetastore ?

BTW, Hive is not creating a Folder (hidden 0 "file") for an empty created managed table. (https://prestosql.slack.com/conversation/CFQAMGHQE/p1553715366000600)

guyco33 picture guyco33 on 4 Jul 2019

Might explains why the hidden 0 "file" is not deleted after the first INSERT https://issues.apache.org/jira/browse/HADOOP-13230

guyco33 picture guyco33 on 7 Jul 2019
👍1

Fixed by merging https://github.com/prestosql/presto/commit/fa1f9325e2465732d615edc13a28fa7affa32e89, thanks!

guyco33 picture guyco33 on 7 Jan 2020
🚀2

For anyone that reaches the same issue: hive.metastore.thrift.delete-files-on-drop=true

rmgpinto picture rmgpinto on 15 Nov 2020
👍2
Was this page helpful?
0 / 5 - 0 ratings

Related issues

anismiles picture anismiles  路  3Comments
findepi picture findepi  路  4Comments
theoretical-olive picture theoretical-olive  路  5Comments
ssquan picture ssquan  路  5Comments
lxynov picture lxynov  路  4Comments