KYLIN system cube failing to update table when run on EMR with S3 as storage and EMRFS

2020-02-24T15:35:46,548 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.kylin.metrics.lib.impl.hive.HiveReservoirReporter - Try to write 113 records2020-02-24T15:35:46,566 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.conf.HiveConf - Found configuration file file:/etc/hive/conf.dist/hive-site.xml2020-02-24T15:35:47,097 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Trying to connect to metastore with URI thrift://ip-1-1-1-1.ec2.internal:90832020-02-24T15:35:47,216 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Opened a connection to metastore, current connections: 12020-02-24T15:35:47,216 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Connected to metastore.2020-02-24T15:35:47,433 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Closed a connection to metastore, current connections: 02020-02-24T15:35:47,824 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.kylin.metrics.lib.impl.hive.HiveProducer - Try to use new partition content path: hdfs://ip-1-1-2-1.ec2.internal:8020/tmp/system_cube/hive_metrics_query_cube_qa/kday_date=2020-02-24/ip-1-1-1-1-1582558547056-part-0000 for metric: METRICS_QUERY_CUBE_QA2020-02-24T15:35:47,959 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.kylin.metrics.lib.impl.hive.HiveProducer - Success to write 37 metrics (METRICS_QUERY_CUBE_QA) to file hdfs://ip-1-1-2-1.ec2.internal:8020/tmp/system_cube/hive_metrics_query_cube_qa/kday_date=2020-02-24/ip-1-1-1-1-1582558547056-part-00002020-02-24T15:35:48,275 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Trying to connect to metastore with URI thrift://ip-1-1-2-1.ec2.internal:90832020-02-24T15:35:48,288 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Opened a connection to metastore, current connections: 12020-02-24T15:35:48,289 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Connected to metastore.2020-02-24T15:35:48,711 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Closed a connection to metastore, current connections: 02020-02-24T15:35:50,223 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.session.SessionState - Created HDFS directory: /tmp/hive/kylin/3f98a154-e471-40fc-9829-4c4283266d462020-02-24T15:35:50,224 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.session.SessionState - Created local directory: /usr/local/kylin/tomcat/temp/kylin/3f98a154-e471-40fc-9829-4c4283266d462020-02-24T15:35:50,232 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.session.SessionState - Created HDFS directory: /tmp/hive/kylin/3f98a154-e471-40fc-9829-4c4283266d46/tmp_space.db2020-02-24T15:35:50,291 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.exec.tez.TezSessionState - User of session id 3f98a154-e471-40fc-9829-4c4283266d46 is kylin2020-02-24T15:35:50,389 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.exec.tez.DagUtils - Jar dir is null / directory doesn't exist. Choosing HIVE_INSTALL_DIR - /user/kylin/.hiveJars2020-02-24T15:35:50,933 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.exec.tez.DagUtils - Resource modification time: 1581024148854 for hdfs://ip-1-1-2-1.ec2.internal:8020/user/kylin/.hiveJars/hive-exec-2.3.6-amzn-0-9f4c4d2a9ab8330bfec9b3ce23e40355288cc5c08a20165b20aca86b2b6c2c95.jar2020-02-24T15:35:51,066 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.security.authorization.plugin.sqlstd.SQLStdHiveAccessController - Created SQLStdHiveAccessController for session context : HiveAuthzSessionContext [sessionString=3f98a154-e471-40fc-9829-4c4283266d46, clientType=HIVECLI]2020-02-24T15:35:51,073 WARN [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.session.SessionState - METASTORE_FILTER_HOOK will be ignored, since hive.security.authorization.manager is set to instance of HiveAuthorizerFactory.2020-02-24T15:35:51,646 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Trying to connect to metastore with URI thrift://ip-1-1-2-1.ec2.internal:90832020-02-24T15:35:51,662 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Opened a connection to metastore, current connections: 12020-02-24T15:35:51,662 INFO [metrics-blocking-reservoir-scheduler-0] hive.metastore - Connected to metastore.2020-02-24T15:35:51,992 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.client.TezClient - Tez Client Version: [ component=tez-api, version=0.9.2, revision=9566b9ed1d86bc2697f1622e4e9825da6c011583, SCM-URL=scm:git:https://gitbox.apache.org/repos/asf/tez.git, buildTime=2019-10-28T16:32:03Z ]2020-02-24T15:35:51,992 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.exec.tez.TezSessionState - Opening new Tez Session (id: 3f98a154-e471-40fc-9829-4c4283266d46, scratch dir: hdfs://ip-1-1-2-1.ec2.internal:8020/tmp/hive/kylin/_tez_session_dir/3f98a154-e471-40fc-9829-4c4283266d46)2020-02-24T15:35:52,578 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.yarn.client.RMProxy - Connecting to ResourceManager at ip-1-1-2-1.ec2.internal/10.127.2.141:80322020-02-24T15:35:52,767 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.client.TezClient - Session mode. Starting session.2020-02-24T15:35:52,839 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.client.TezClientUtils - Using tez.lib.uris value from configuration: hdfs:///apps/tez/tez.tar.gz2020-02-24T15:35:52,839 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.client.TezClientUtils - Using tez.lib.uris.classpath value from configuration: null2020-02-24T15:35:52,871 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hdfs.DFSClient - Created HDFS_DELEGATION_TOKEN token 856 for kylin on 10.127.2.141:80202020-02-24T15:35:53,280 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.common.security.TokenCache - Got dt for hdfs://ip-1-1-2-1.ec2.internal:8020; Kind: HDFS_DELEGATION_TOKEN, Service: 10.127.2.141:8020, Ident: (HDFS_DELEGATION_TOKEN token 856 for kylin)2020-02-24T15:35:53,280 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.common.security.TokenCache - Got dt for hdfs://ip-1-1-2-1.ec2.internal:8020; Kind: kms-dt, Service: 10.127.2.141:9700, Ident: (owner=kylin, renewer=yarn, realUser=, issueDate=1582558553105, maxDate=1583163353105, sequenceNumber=853, masterKeyId=53)2020-02-24T15:35:53,310 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.client.TezClient - Tez system stage directory hdfs://ip-1-1-2-1.ec2.internal:8020/tmp/hive/kylin/_tez_session_dir/3f98a154-e471-40fc-9829-4c4283266d46/.tez/application_1578089000827_0674 doesn't exist and is created2020-02-24T15:35:54,257 INFO [BadQueryDetector] org.apache.kylin.rest.service.BadQueryDetector - Detect bad query.2020-02-24T15:35:54,620 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.yarn.client.api.impl.TimelineClientImpl - Timeline service address: http://ip-1-1-2-1.ec2.internal:8188/ws/v1/timeline/2020-02-24T15:35:55,040 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.yarn.client.api.impl.YarnClientImpl - Submitted application application_1578089000827_06742020-02-24T15:35:55,041 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.tez.client.TezClient - The url to track the Tez Session: http://ip-1-1-2-1.ec2.internal:20888/proxy/application_1578089000827_0674/2020-02-24T15:35:57,000 INFO [FetcherRunner 1354629870-25] org.apache.kylin.job.impl.threadpool.DefaultFetcherRunner - Job Fetcher: 0 should running, 0 actual running, 0 stopped, 0 ready, 20 already succeed, 1 error, 0 discarded, 0 others2020-02-24T15:35:59,829 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Compiling command(queryId=kylin_20200224153550_249ef9e2-5723-403f-8ef9-e1a43de9b661): ALTER TABLE KYLIN.HIVE_METRICS_QUERY_QA ADD IF NOT EXISTS PARTITION (kday_date='2020-02-24')2020-02-24T15:36:01,467 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Semantic Analysis Completed2020-02-24T15:36:01,471 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Returning Hive schema: Schema(fieldSchemas:null, properties:null)2020-02-24T15:36:01,485 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Completed compiling command(queryId=kylin_20200224153550_249ef9e2-5723-403f-8ef9-e1a43de9b661); Time taken: 1.708 seconds2020-02-24T15:36:01,485 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Concurrency mode is disabled, not creating a lock manager2020-02-24T15:36:01,485 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Executing command(queryId=kylin_20200224153550_249ef9e2-5723-403f-8ef9-e1a43de9b661): ALTER TABLE KYLIN.HIVE_METRICS_QUERY_QA ADD IF NOT EXISTS PARTITION (kday_date='2020-02-24')2020-02-24T15:36:01,506 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Starting task [Stage-0:DDL] in serial mode2020-02-24T15:36:02,952 INFO [metrics-blocking-reservoir-scheduler-0] hive.ql.metadata.Hive - Dumping metastore api call timing information for : execution phase2020-02-24T15:36:02,952 INFO [metrics-blocking-reservoir-scheduler-0] hive.ql.metadata.Hive - Total time spent in this metastore function was greater than 1000ms : add_partitions(List, boolean, boolean, )=11912020-02-24T15:36:02,952 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - Completed executing command(queryId=kylin_20200224153550_249ef9e2-5723-403f-8ef9-e1a43de9b661); Time taken: 1.467 secondsOK2020-02-24T15:36:02,953 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.hadoop.hive.ql.Driver - OK2020-02-24T15:36:02,954 INFO [metrics-blocking-reservoir-scheduler-0] org.apache.kylin.metrics.lib.impl.hive.HiveProducer - Try to use new partition content path: s3://my_bucket/warehouse/kylin.db/hive_metrics_query_qa/kday_date=2020-02-24/ip-1-1-1-1-1582558548273-part-0000 for metric: METRICS_QUERY_QA2020-02-24T15:36:03,322 INFO [metrics-blocking-reservoir-scheduler-0] com.amazon.ws.emr.hadoop.fs.cse.CSEMultipartUploadOutputStream - close closed:false s3://my_bucket/warehouse/kylin.db/hive_metrics_query_qa/kday_date=2020-02-24/ip-1-1-1-1-1582558548273-part-00002020-02-24T15:36:03,847 INFO [metrics-blocking-reservoir-scheduler-0] com.amazon.ws.emr.hadoop.fs.s3.upload.dispatch.DefaultMultipartUploadDispatcher - Completed multipart upload of 1 parts 0 bytes2020-02-24T15:36:04,203 INFO [metrics-blocking-reservoir-scheduler-0] com.amazon.ws.emr.hadoop.fs.cse.CSEMultipartUploadOutputStream - Finished uploading my_bucket/warehouse/kylin.db/hive_metrics_query_qa/kday_date=2020-02-24/ip-1-1-1-1-1582558548273-part-0000. Elapsed seconds: 0.2020-02-24T15:36:04,284 ERROR [metrics-blocking-reservoir-scheduler-0] org.apache.kylin.metrics.lib.impl.hive.HiveReservoirReporter - nulljava.lang.UnsupportedOperationException at com.amazon.ws.emr.hadoop.fs.s3n2.S3NativeFileSystem2.append(S3NativeFileSystem2.java:150) ~[emrfs-hadoop-assembly-2.37.0.jar:?] at org.apache.hadoop.fs.FileSystem.append(FileSystem.java:1181) ~[hadoop-common-2.8.5-amzn-5.jar:?] at com.amazon.ws.emr.hadoop.fs.EmrFileSystem.append(EmrFileSystem.java:295) ~[emrfs-hadoop-assembly-2.37.0.jar:?] at org.apache.kylin.metrics.lib.impl.hive.HiveProducer.write(HiveProducer.java:204) ~[kylin-metrics-reporter-hive-3.0.0.jar:3.0.0] at org.apache.kylin.metrics.lib.impl.hive.HiveProducer.send(HiveProducer.java:134) ~[kylin-metrics-reporter-hive-3.0.0.jar:3.0.0] at org.apache.kylin.metrics.lib.impl.hive.HiveReservoirReporter$HiveReservoirListener.onRecordUpdate(HiveReservoirReporter.java:144) [kylin-metrics-reporter-hive-3.0.0.jar:3.0.0] at org.apache.kylin.metrics.lib.impl.BlockingReservoir.notifyListenerOfUpdatedRecord(BlockingReservoir.java:117) [kylin-core-metrics-3.0.0.jar:3.0.0] at org.apache.kylin.metrics.lib.impl.BlockingReservoir.onRecordUpdate(BlockingReservoir.java:105) [kylin-core-metrics-3.0.0.jar:3.0.0] at org.apache.kylin.metrics.lib.impl.BlockingReservoir.access$300(BlockingReservoir.java:37) [kylin-core-metrics-3.0.0.jar:3.0.0] at org.apache.kylin.metrics.lib.impl.BlockingReservoir$ReporterRunnable.run(BlockingReservoir.java:171) [kylin-core-metrics-3.0.0.jar:3.0.0] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_242]2020-02-24T15:36:04,290 WARN [metrics-blocking-reservoir-scheduler-0] org.apache.kylin.metrics.lib.impl.BlockingReservoir - It fails to notify listener org.apache.kylin.metrics.lib.impl.hive.HiveReservoirReporter$HiveReservoirListener@1d460286 of updated record size 1132