2022-10-26 07:38:15,756 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/hConf.xml 2022-10-26 07:38:15,771 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/hConf.xml 2022-10-26 07:38:15,773 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/program.options.json 2022-10-26 07:38:15,786 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/program.options.json 2022-10-26 07:38:15,789 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/cConf.xml 2022-10-26 07:38:15,803 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/cConf.xml 2022-10-26 07:38:15,806 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:16,590 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:16,593 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/spark-defaults.conf3504512643549673422.tmp 2022-10-26 07:38:16,607 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/spark-defaults.conf3504512643549673422.tmp 2022-10-26 07:38:16,610 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/spark.default.test.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56/program.jar 2022-10-26 07:38:16,764 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/spark.default.test.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56/program.jar 2022-10-26 07:38:16,769 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/py4j-0.10.9-src.zip 2022-10-26 07:38:16,783 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/py4j-0.10.9-src.zip 2022-10-26 07:38:16,786 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:17,550 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:17,553 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@872] - Saving twill specification for spark.default.test.DataStreamsSparkStreaming to /tmp/runtime.config.jar5829944738190464809/twillSpec.json 2022-10-26 07:38:17,556 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@891] - Save twill arguments to /tmp/runtime.config.jar5829944738190464809/arguments.json 2022-10-26 07:38:17,557 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@906] - Create and upload /tmp/runtime.config.jar5829944738190464809 2022-10-26 07:38:17,571 - INFO [program-start-2:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 0.5 and memory multiplier 0.5 for program in namespace 'default' 2022-10-26 07:38:17,572 - INFO [program-start-2:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 0.5 and memory multiplier 0.5 for program in namespace 'default' 2022-10-26 07:38:17,613 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService@687] - Monitoring application spark.default.test.DataStreamsSparkStreaming with run 21de2bd4-5501-11ed-82a8-ca248ecd3c56 starts in 300000 MILLISECONDS 2022-10-26 07:38:17,620 - INFO [program-start-2:i.c.c.k.r.KubeTwillPreparer@756] - Created Deployment cdap-cdap-spark-default-test-datastreamssparkstreaming-21de2bd4-5501-11ed-82a8-ca248ecd3c56 in Kubernetes 2022-10-26 07:38:17,620 - DEBUG [program-start-2:i.c.c.i.a.r.d.DistributedProgramRunner@784] - Cleanup tmp files for program:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming: /data/tmp/1666769892165-0 2022-10-26 07:38:17,633 - INFO [program-start-2:i.c.c.i.a.r.d.AbstractTwillProgramController@69] - Twill program running: program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56, twill runId: 21de2bd4-5501-11ed-82a8-ca248ecd3c56 2022-10-26 07:38:19,590 - INFO [program.status:i.c.c.i.a.s.RunRecordMonitorService@151] - Removed request with runId program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56. Counter has 0 concurrent launching requests. 2022-10-26 07:38:34,900 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService$1@738] - Application spark.default.test.DataStreamsSparkStreaming with run 21de2bd4-5501-11ed-82a8-ca248ecd3c56 is available in Kubernetes [root@ip-172-31-30-183 cdap-operator]# clear [root@ip-172-31-30-183 cdap-operator]# kubectl logs cdap-cdap-appfabric-0 Wed Oct 26 07:17:39 UTC 2022 Running class io.cdap.cdap.master.environment.k8s.AppFabricServiceMain with arguments: --env=k8s SLF4J: Class path contains multiple SLF4J bindings. SLF4J: Found binding in [jar:file:/opt/cdap/master/lib/ch.qos.logback.logback-classic-1.2.11.jar!/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: Found binding in [jar:file:/opt/hadoop/hadoop-2.9.2/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. 07:17:39,787 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 07:17:39,787 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/etc/cdap/conf/logback.xml] 07:17:39,788 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath. 07:17:39,789 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/etc/cdap/conf/logback.xml] 07:17:39,789 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/opt/cdap/master/conf/logback.xml] 07:17:39,954 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set 07:17:39,970 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/etc/cdap/conf/logback.xml] 07:17:39,970 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 30 seconds 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.commons.beanutils] to ERROR 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.zookeeper.server] to ERROR 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.zookeeper] to ERROR 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.ning] to WARN 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.spark] to WARN 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.spark-project] to WARN 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop] to WARN 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.ipc.Client] to ERROR 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hive] to WARN 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.quartz.core] to WARN 07:17:39,973 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse.jetty] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.netty.util.internal] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.tephra.distributed.AbstractClientProvider] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.mortbay.log] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [SecurityLogger.org.apache.hadoop.security.authorize.ServiceAuthorizationManager] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [SecurityLogger.org.apache.hadoop.ipc.Server] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.security.token.Token] to ERROR 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.metrics2] to ERROR 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [akka] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [Remoting] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.sun.jersey] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [WriteAheadLogManager ] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka.common.config.AbstractConfig] to WARN 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.http.HttpRequestLog] to ERROR 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.twill] to INFO 07:17:39,974 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.twill.internal.kafka.client.SimpleKafkaConsumer] to WARN 07:17:39,975 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.cdap] to INFO 07:17:39,975 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.http.HttpDispatcher] to OFF 07:17:39,975 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.cdap] to DEBUG 07:17:39,975 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.wrangler] to DEBUG 07:17:39,975 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.hdfs.DataStreamer] to ERROR 07:17:39,975 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.spark_project] to DEBUG 07:17:39,975 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 07:17:39,978 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [Console] 07:17:39,984 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 07:17:40,030 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ERROR SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder] 07:17:40,030 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [Console] to Logger[ROOT] 07:17:40,031 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 07:17:40,031 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1b083826 - Registering current configuration as safe fallback point SLF4J: Class path contains multiple SLF4J bindings. SLF4J: Found binding in [jar:file:/opt/cdap/master/lib/ch.qos.logback.logback-classic-1.2.11.jar!/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: Found binding in [jar:file:/opt/hadoop/hadoop-2.9.2/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. 07:17:40,320 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 07:17:40,320 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/etc/cdap/conf/logback.xml] 07:17:40,321 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath. 07:17:40,321 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/etc/cdap/conf/logback.xml] 07:17:40,321 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/opt/cdap/master/conf/logback.xml] 07:17:40,568 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set 07:17:40,578 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/etc/cdap/conf/logback.xml] 07:17:40,578 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 30 seconds 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.commons.beanutils] to ERROR 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.zookeeper.server] to ERROR 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.zookeeper] to ERROR 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.ning] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.spark] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.spark-project] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.ipc.Client] to ERROR 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hive] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.quartz.core] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse.jetty] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.netty.util.internal] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.tephra.distributed.AbstractClientProvider] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.mortbay.log] to WARN 07:17:40,584 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [SecurityLogger.org.apache.hadoop.security.authorize.ServiceAuthorizationManager] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [SecurityLogger.org.apache.hadoop.ipc.Server] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.security.token.Token] to ERROR 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.metrics2] to ERROR 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [akka] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [Remoting] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.sun.jersey] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [WriteAheadLogManager ] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka.common.config.AbstractConfig] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.http.HttpRequestLog] to ERROR 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.twill] to INFO 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.twill.internal.kafka.client.SimpleKafkaConsumer] to WARN 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.cdap] to INFO 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.http.HttpDispatcher] to OFF 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.cdap] to DEBUG 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.cdap.wrangler] to DEBUG 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.hadoop.hdfs.DataStreamer] to ERROR 07:17:40,585 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.spark_project] to DEBUG 07:17:40,585 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 07:17:40,590 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [Console] 07:17:40,597 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 07:17:40,634 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ERROR 07:17:40,634 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [Console] to Logger[ROOT] 07:17:40,634 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 07:17:40,635 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@301ec38b - Registering current configuration as safe fallback point SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder] 2022-10-26 07:17:40,639 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@131] - Initializing master service class io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:41,681 - DEBUG [main:i.c.c.c.g.DFSLocationModule$LocationFactoryProvider@76] - Location namespace is /cdap 2022-10-26 07:17:41,814 - WARN [main:o.a.h.u.NativeCodeLoader@62] - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable 2022-10-26 07:17:41,885 - DEBUG [main:i.c.c.c.g.FileContextProvider@68] - Getting filesystem for user root 2022-10-26 07:17:42,965 - INFO [main:i.c.c.m.e.k.KubeMasterEnvironment@243] - Initializing Kubernetes environment 2022-10-26 07:17:43,770 - INFO [main:i.c.c.m.e.k.KubeMasterEnvironment@365] - Kubernetes environment initialized with pod labels {cdap.container.AppFabric=cdap, cdap.instance=cdap} 2022-10-26 07:17:44,936 - INFO [main:i.c.c.l.a.LogAppenderInitializer@107] - Initializing log appender RemoteLogAppender 2022-10-26 07:17:45,312 - DEBUG [RemoteLogPublisher:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service RemoteLogPublisher 2022-10-26 07:17:45,508 - DEBUG [main:i.c.c.c.g.DFSLocationModule$LocationFactoryProvider@76] - Location namespace is /cdap 2022-10-26 07:17:45,514 - DEBUG [main:i.c.c.c.g.FileContextProvider@68] - Getting filesystem for user root 2022-10-26 07:17:45,734 - INFO [kube-discovery-service:i.c.c.k.c.AbstractWatcherThread@125] - Start watching for changes in kubernetes resource type class io.kubernetes.client.openapi.models.V1Service 2022-10-26 07:17:45,740 - INFO [main:i.c.c.s.d.s.PostgreSqlStorageProvider@187] - Successfully loaded org.postgresql.Driver from /opt/cdap/master/ext/jdbc 2022-10-26 07:17:45,744 - INFO [main:i.c.c.s.d.s.PostgreSqlStorageProvider@126] - Creating the DataSource with jdbc url: jdbc:postgresql://postgres-postgresql.default.svc.cluster.local:5432/cdap 2022-10-26 07:17:46,091 - DEBUG [main:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module io.cdap.cdap.data2.dataset2.lib.kv.InMemoryKVTableDefinition$Module to system namespace 2022-10-26 07:17:46,237 - WARN [main:i.c.c.e.c.ExploreFacade@55] - Explore functionality for datasets is disabled. All calls to enable explore will be no-ops 2022-10-26 07:17:46,343 - DEBUG [main:i.c.c.s.a.AccessControllerInstantiator@101] - Authorization is disabled. Authorization can be enabled by setting security.authorization.enabled to true. 2022-10-26 07:17:46,345 - DEBUG [main:i.c.c.s.a.AccessControllerInstantiator@101] - Authorization is disabled. Authorization can be enabled by setting security.authorization.enabled to true. 2022-10-26 07:17:46,346 - DEBUG [main:i.c.c.s.a.AccessControllerInstantiator@101] - Authorization is disabled. Authorization can be enabled by setting security.authorization.enabled to true. 2022-10-26 07:17:46,368 - DEBUG [main:i.c.c.i.e.EventWriterExtensionProvider@53] - No event writers enabled. 2022-10-26 07:17:46,375 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@208] - Service io.cdap.cdap.master.environment.k8s.AppFabricServiceMain initialized 2022-10-26 07:17:46,376 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@213] - Starting all services for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,376 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service MessagingMetricsCollectionService [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,378 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service OperationalStatsService [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,395 - DEBUG [OperationalStatsService:i.c.c.o.OperationalStatsService@91] - Registering operational extension: io.cdap.cdap.operations.cdap.CDAPEntities@bf3aa3f; extension id: OperationalExtensionId{serviceName='cdap', statType='entities'} 2022-10-26 07:17:46,400 - DEBUG [OperationalStatsService:i.c.c.o.OperationalStatsService@91] - Registering operational extension: io.cdap.cdap.operations.cdap.CDAPLoad@17c69d79; extension id: OperationalExtensionId{serviceName='cdap', statType='lasthourload'} 2022-10-26 07:17:46,401 - DEBUG [OperationalStatsService:i.c.c.o.OperationalStatsService@91] - Registering operational extension: io.cdap.cdap.operations.cdap.CDAPInfo@6563f461; extension id: OperationalExtensionId{serviceName='cdap', statType='info'} 2022-10-26 07:17:46,401 - DEBUG [OperationalStatsService:i.c.c.o.OperationalStatsService@91] - Registering operational extension: io.cdap.cdap.operations.cdap.CDAPTransactions@5dd3cb97; extension id: OperationalExtensionId{serviceName='cdap', statType='transactions'} 2022-10-26 07:17:46,402 - INFO [OperationalStatsService:i.c.c.o.OperationalStatsService@98] - Successfully started Operational Stats Service... 2022-10-26 07:17:46,402 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service DefaultSecureStoreService [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,414 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service DatasetOpExecutorService{bindAddress=/0.0.0.0:0} for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,418 - INFO [DatasetOpExecutorService STARTING:i.c.c.d.d.d.s.e.DatasetOpExecutorService@82] - Starting DatasetOpExecutorService... 2022-10-26 07:17:46,704 - INFO [DatasetOpExecutorService STARTING:i.c.c.k.d.KubeDiscoveryService@268] - Service created in kubernetes with name cdap-cdap-dataset-executor and port 36063 2022-10-26 07:17:46,705 - INFO [DatasetOpExecutorService STARTING:i.c.c.d.d.d.s.e.DatasetOpExecutorService@87] - DatasetOpExecutorService started successfully on /0:0:0:0:0:0:0:0:36063 2022-10-26 07:17:46,706 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service DatasetServiceStore [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,720 - INFO [DatasetServiceStore STARTING:i.c.c.d.d.InMemoryDatasetFramework@254] - Created dataset dataset:system.cdap.services.instances of type io.cdap.cdap.data2.dataset2.lib.kv.NoTxKeyValueTable 2022-10-26 07:17:46,731 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service TwillRunnerServiceWrapper [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,743 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service TwillRunnerServiceWrapper [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,744 - DEBUG [TwillRunnerServiceWrapper STARTING:i.c.c.k.r.KubeTwillRunnerService@275] - Starting KubeTwillRunnerService with enabled monitor 2022-10-26 07:17:46,758 - INFO [kube-deployments-watch:i.c.c.k.c.AbstractWatcherThread@125] - Start watching for changes in kubernetes resource type class io.kubernetes.client.openapi.models.V1Deployment 2022-10-26 07:17:46,766 - INFO [kube-jobs-watch:i.c.c.k.c.AbstractWatcherThread@125] - Start watching for changes in kubernetes resource type class io.kubernetes.client.openapi.models.V1Job 2022-10-26 07:17:46,775 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service EndureService{DatasetService} for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,776 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service AppFabricServer [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:46,783 - INFO [dataset.service-startup:i.c.c.d.d.d.s.DatasetService@141] - Starting DatasetService... 2022-10-26 07:17:46,787 - INFO [ProvisioningService STARTING:i.c.c.i.p.ProvisioningService@168] - Starting ProvisioningService 2022-10-26 07:17:46,795 - INFO [ApplicationLifecycleService STARTING:i.c.c.i.a.s.ApplicationLifecycleService@209] - Starting ApplicationLifecycleService 2022-10-26 07:17:46,801 - INFO [BootstrapService STARTING:i.c.c.i.b.BootstrapService@83] - Starting BootstrapService 2022-10-26 07:17:46,802 - DEBUG [program.status:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service program.status 2022-10-26 07:17:46,813 - DEBUG [program.stop.service:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service program.stop.service 2022-10-26 07:17:46,784 - INFO [kube-statefulsets-watch:i.c.c.k.c.AbstractWatcherThread@125] - Start watching for changes in kubernetes resource type class io.kubernetes.client.openapi.models.V1StatefulSet 2022-10-26 07:17:46,817 - INFO [ScheduledRunRecordCorrectorService STARTING:i.c.c.i.a.s.RunRecordCorrectorService@157] - Starting RunRecordCorrectorService 2022-10-26 07:17:46,821 - DEBUG [ProgramRunStatusMonitorService:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service ProgramRunStatusMonitorService 2022-10-26 07:17:46,823 - INFO [run-record-monitor-service-cleanup-scheduler:i.c.c.i.a.s.RunRecordMonitorService@78] - RunRecordMonitorService started. 2022-10-26 07:17:46,841 - INFO [DistributedTimeSchedulerService STARTING:i.c.c.i.a.r.s.DistributedTimeSchedulerService@75] - Starting scheduler. 2022-10-26 07:17:46,899 - INFO [BootstrapService STARTING:i.c.c.i.b.BootstrapService@110] - Started BootstrapService 2022-10-26 07:17:46,974 - DEBUG [ProvisioningService STARTING:i.c.c.i.p.DefaultProvisionerConfigProvider@113] - Unable to find JSON config file /opt/cdap/master/lib/native.json for provisioner native 2022-10-26 07:17:46,984 - DEBUG [ProvisioningService STARTING:i.c.c.i.p.ProvisioningService@536] - Provisioners = {gcp-existing-dataproc=io.cdap.cdap.runtime.spi.provisioner.dataproc.ExistingDataprocProvisioner@46c1e67, native=io.cdap.cdap.internal.provision.NativeProvisioner@58daeaa9, tethering=io.cdap.cdap.internal.tethering.runtime.spi.provisioner.TetheringProvisioner@396b354d, gcp-dataproc=io.cdap.cdap.runtime.spi.provisioner.dataproc.DataprocProvisioner@140ba19, remote-hadoop=io.cdap.cdap.runtime.spi.provisioner.remote.RemoteHadoopProvisioner@653b0370, aws-emr=io.cdap.cdap.runtime.spi.provisioner.emr.ElasticMapReduceProvisioner@6abb32dc} 2022-10-26 07:17:46,988 - INFO [Endure-Service-DistributedTimeSchedulerService:o.q.s.RAMJobStore@155] - RAMJobStore initialized. 2022-10-26 07:17:47,009 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.orderedTable-leveldb, className: io.cdap.cdap.data2.dataset2.module.lib.leveldb.LevelDBTableModule, jarLocation: [local] 2022-10-26 07:17:47,111 - DEBUG [bootstrap-service:i.c.c.i.b.e.BaseStepExecutor@63] - Executing bootstrap step Create native profile 2022-10-26 07:17:47,160 - DEBUG [bootstrap-service:i.c.c.i.b.e.BaseStepExecutor@66] - Bootstrap step Create native profile completed successfully 2022-10-26 07:17:47,173 - DEBUG [bootstrap-service:i.c.c.i.b.e.BaseStepExecutor@63] - Executing bootstrap step Create default namespace 2022-10-26 07:17:47,189 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.metricsTable-leveldb, className: io.cdap.cdap.data2.dataset2.module.lib.leveldb.LevelDBMetricsTableModule, jarLocation: [local] 2022-10-26 07:17:47,202 - DEBUG [Endure-Service-DistributedTimeSchedulerService:i.c.c.i.a.r.s.s.DatasetBasedTimeScheduleStore@214] - Schedule: stored job with key NewPausedTriggers.EmptyJob 2022-10-26 07:17:47,205 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.core, className: io.cdap.cdap.data2.dataset2.lib.table.CoreDatasetsModule, jarLocation: [local] 2022-10-26 07:17:47,232 - INFO [Endure-Service-DistributedTimeSchedulerService:i.c.c.i.a.r.s.AbstractTimeSchedulerService@54] - Started time scheduler 2022-10-26 07:17:47,236 - WARN [bootstrap-service:i.c.c.e.c.ExploreFacade@55] - Explore functionality for datasets is disabled. All calls to enable explore will be no-ops 2022-10-26 07:17:47,271 - INFO [core scheduler service STARTING:i.c.c.s.CoreSchedulerService@151] - Cleaning up jobs in state PENDING_LAUNCH. 2022-10-26 07:17:47,274 - INFO [ConstraintCheckerService STARTING:i.c.c.s.ConstraintCheckerService@96] - Starting ConstraintCheckerService. 2022-10-26 07:17:47,353 - INFO [ConstraintCheckerService STARTING:i.c.c.s.ConstraintCheckerService@105] - Started ConstraintCheckerService. state: STARTING 2022-10-26 07:17:47,372 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.fileSet, className: io.cdap.cdap.data2.dataset2.lib.file.FileSetModule, jarLocation: [local] 2022-10-26 07:17:47,361 - INFO [ScheduleNotificationSubscriberService STARTING:i.c.c.s.ScheduleNotificationSubscriberService@91] - Starting ScheduleNotificationSubscriberService 2022-10-26 07:17:47,380 - DEBUG [scheduler-notification-subscriber-0:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service scheduler.event 2022-10-26 07:17:47,395 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.timePartitionedFileSet, className: io.cdap.cdap.data2.dataset2.lib.partitioned.TimePartitionedFileSetModule, jarLocation: [local] 2022-10-26 07:17:47,453 - DEBUG [scheduler-notification-subscriber-0:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service scheduler.data.event 2022-10-26 07:17:47,458 - DEBUG [scheduler-notification-subscriber-0:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service scheduler.program.event 2022-10-26 07:17:47,472 - INFO [core scheduler service STARTING:i.c.c.s.CoreSchedulerService$1@128] - Started core scheduler service. 2022-10-26 07:17:47,476 - INFO [AppFabricServer STARTING:i.c.c.i.a.s.AppFabricServer@232] - AppFabric HTTP Service announced at /0:0:0:0:0:0:0:0:42799 2022-10-26 07:17:47,501 - INFO [AppFabricServer STARTING:i.c.c.k.d.KubeDiscoveryService@268] - Service created in kubernetes with name cdap-cdap-appfabric and port 42799 2022-10-26 07:17:47,535 - INFO [AppFabricServer STARTING:i.c.c.k.d.KubeDiscoveryService@268] - Service created in kubernetes with name cdap-cdap-secure-store-service and port 42799 2022-10-26 07:17:47,539 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.partitionedFileSet, className: io.cdap.cdap.data2.dataset2.lib.partitioned.PartitionedFileSetModule, jarLocation: [local] 2022-10-26 07:17:47,550 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service EndureService{NamespaceInitializerService} for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:47,554 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@215] - Starting service MasterTaskExecutorService [NEW] for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain 2022-10-26 07:17:47,556 - INFO [main:i.c.c.m.e.k.AbstractServiceMain@218] - All services for io.cdap.cdap.master.environment.k8s.AppFabricServiceMain started 2022-10-26 07:17:47,591 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.objectMappedTable, className: io.cdap.cdap.data2.dataset2.lib.table.ObjectMappedTableModule, jarLocation: [local] 2022-10-26 07:17:47,672 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.cube, className: io.cdap.cdap.data2.dataset2.lib.table.CubeModule, jarLocation: [local] 2022-10-26 07:17:47,736 - DEBUG [DefaultDatasetTypeService STARTING:i.c.c.d.d.d.t.DatasetTypeManager@110] - adding module: dataset_module:system.externalDataset, className: io.cdap.cdap.data2.dataset2.lib.external.ExternalDatasetModule, jarLocation: [local] 2022-10-26 07:17:47,749 - INFO [bootstrap-service:i.c.c.i.a.n.DefaultNamespaceAdmin@219] - Namespace namespace:default created with meta NamespaceMeta{name='default', description='This is the default namespace, which is automatically created, and is always available.', generation=0, config=NamespaceConfig{configs={scheduler.queue.name=, explore.as.principal=true}}} 2022-10-26 07:17:47,749 - INFO [bootstrap-service:i.c.c.i.b.e.DefaultNamespaceCreator@51] - Successfully created namespace 'NamespaceMeta{name='default', description='This is the default namespace, which is automatically created, and is always available.', generation=0, config=NamespaceConfig{configs={scheduler.queue.name=, explore.as.principal=true}}}'. 2022-10-26 07:17:47,750 - DEBUG [bootstrap-service:i.c.c.i.b.e.BaseStepExecutor@66] - Bootstrap step Create default namespace completed successfully 2022-10-26 07:17:47,750 - DEBUG [bootstrap-service:i.c.c.i.b.e.BaseStepExecutor@63] - Executing bootstrap step Load system artifacts 2022-10-26 07:17:47,757 - INFO [dataset.service-startup:i.c.c.d.d.d.s.DatasetTypeHandler@62] - Starting DatasetTypeHandler 2022-10-26 07:17:47,757 - DEBUG [runtime-scheduler-0:i.c.c.i.a.r.d.r.RemoteExecutionTwillRunnerService@480] - Initialization completed with 0 runs added 2022-10-26 07:17:47,766 - INFO [dataset.service-startup:i.c.c.d.d.d.s.DatasetService@193] - Waiting for dataset.executor service to be discoverable 2022-10-26 07:17:47,824 - INFO [kube-discovery-service:i.c.c.d.d.d.s.DatasetService@151] - Discovered dataset.executor service 2022-10-26 07:17:47,824 - INFO [dataset.service-startup:i.c.c.d.d.d.s.DatasetService@176] - Announcing DatasetService for discovery... 2022-10-26 07:17:47,854 - INFO [dataset.service-startup:i.c.c.k.d.KubeDiscoveryService@268] - Service created in kubernetes with name cdap-cdap-dataset-service and port 44515 2022-10-26 07:17:47,855 - INFO [dataset.service-startup:i.c.c.d.d.d.s.DatasetService@181] - DatasetService started successfully on /0:0:0:0:0:0:0:0:44515 2022-10-26 07:17:47,922 - DEBUG [system-artifact-loader-0:i.c.c.a.r.s.SparkProgramRuntimeProvider@169] - using sparkCompat SPARK3_2_12 2022-10-26 07:17:48,079 - DEBUG [system-artifact-loader-11:i.c.c.a.r.s.SparkPackageUtils@317] - Located Spark library in in /opt/spark/spark-3.1.1-bin-without-hadoop/jars 2022-10-26 07:17:48,584 - WARN [OperationalStatsService:i.c.c.o.OperationalStatsService@144] - Failed to collect stats for service CDAP of type lastHourLoad due to Unable to discover metrics service endpoint 2022-10-26 07:17:52,845 - INFO [system-artifact-loader-1:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.cdap-data-pipeline.6.9.0-SNAPSHOT. 2022-10-26 07:17:52,845 - INFO [system-artifact-loader-11:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.delta-proto.0.8.0-SNAPSHOT. 2022-10-26 07:17:52,850 - INFO [system-artifact-loader-2:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.delta-test.0.8.0-SNAPSHOT. 2022-10-26 07:17:52,850 - INFO [system-artifact-loader-3:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.kafka-plugins-common.3.2.0-SNAPSHOT. 2022-10-26 07:17:52,851 - INFO [system-artifact-loader-0:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.wrangler-storage.4.9.0-SNAPSHOT. 2022-10-26 07:17:52,852 - INFO [system-artifact-loader-8:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.hydrator-common.2.11.0-SNAPSHOT. 2022-10-26 07:17:52,852 - INFO [system-artifact-loader-5:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.cdap-program-report.6.9.0-SNAPSHOT. 2022-10-26 07:17:52,853 - INFO [system-artifact-loader-12:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.delta-app.0.8.0-SNAPSHOT. 2022-10-26 07:17:52,855 - INFO [system-artifact-loader-10:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.delta-plugins-common.0.8.0-SNAPSHOT. 2022-10-26 07:17:52,857 - INFO [system-artifact-loader-15:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.wrangler-proto.4.9.0-SNAPSHOT. 2022-10-26 07:17:53,826 - INFO [system-artifact-loader-6:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.wrangler-service.4.9.0-SNAPSHOT. 2022-10-26 07:17:53,843 - INFO [system-artifact-loader-16:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.wrangler-api.4.9.0-SNAPSHOT. 2022-10-26 07:17:53,851 - INFO [system-artifact-loader-9:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.mmds-app.1.12.0-SNAPSHOT. 2022-10-26 07:17:53,856 - INFO [system-artifact-loader-14:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.cdap-data-streams.6.9.0-SNAPSHOT. 2022-10-26 07:17:53,856 - INFO [system-artifact-loader-7:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.database-commons.1.10.0-SNAPSHOT. 2022-10-26 07:17:53,862 - INFO [system-artifact-loader-17:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.mmds-model.1.12.0-SNAPSHOT. 2022-10-26 07:17:53,864 - INFO [system-artifact-loader-4:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-common.2.11.0-SNAPSHOT. 2022-10-26 07:17:53,870 - INFO [system-artifact-loader-13:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.delta-api.0.8.0-SNAPSHOT. 2022-10-26 07:17:57,928 - INFO [system-artifact-loader-27:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.delta-transformation.0.4.0-SNAPSHOT. 2022-10-26 07:17:59,931 - INFO [system-artifact-loader-45:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.bigquery-delta-plugins.0.8.0-SNAPSHOT. 2022-10-26 07:18:00,959 - INFO [system-artifact-loader-46:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.sqlserver-delta-plugins.0.8.0-SNAPSHOT. 2022-10-26 07:18:02,041 - INFO [system-artifact-loader-21:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.filesource-common.1.15.0-SNAPSHOT. 2022-10-26 07:18:02,111 - INFO [system-artifact-loader-39:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.http-plugins.2.11.0-SNAPSHOT. 2022-10-26 07:18:02,138 - INFO [system-artifact-loader-18:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-json.2.11.0-SNAPSHOT. 2022-10-26 07:18:03,103 - INFO [system-artifact-loader-48:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.cloudsql-postgresql-plugin.1.10.0-SNAPSHOT. 2022-10-26 07:18:03,131 - INFO [system-artifact-loader-32:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.condition-plugins.1.12.0-SNAPSHOT. 2022-10-26 07:18:03,152 - INFO [system-artifact-loader-35:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.mysql-delta-plugins.0.8.0-SNAPSHOT. 2022-10-26 07:18:03,156 - INFO [system-artifact-loader-49:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.datastream-delta-plugins.0.6.0-SNAPSHOT. 2022-10-26 07:18:04,223 - INFO [system-artifact-loader-42:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-blob.2.11.0-SNAPSHOT. 2022-10-26 07:18:04,252 - INFO [system-artifact-loader-19:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.database-plugins.2.11.0-SNAPSHOT. 2022-10-26 07:18:04,394 - INFO [system-artifact-loader-36:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-text.2.11.0-SNAPSHOT. 2022-10-26 07:18:04,543 - INFO [system-artifact-loader-34:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-delimited.2.11.0-SNAPSHOT. 2022-10-26 07:18:04,544 - INFO [system-artifact-loader-22:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-orc.2.11.0-SNAPSHOT. 2022-10-26 07:18:05,594 - INFO [system-artifact-loader-47:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.transform-plugins.2.11.0-SNAPSHOT. 2022-10-26 07:18:05,594 - INFO [system-artifact-loader-30:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.spark-plugins.2.11.0-SNAPSHOT. 2022-10-26 07:18:05,604 - INFO [system-artifact-loader-37:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.oracle-plugin.1.10.0-SNAPSHOT. 2022-10-26 07:18:05,608 - INFO [system-artifact-loader-44:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.cloudsql-mysql-plugin.1.10.0-SNAPSHOT. 2022-10-26 07:18:05,612 - INFO [system-artifact-loader-31:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.mysql-plugin.1.10.0-SNAPSHOT. 2022-10-26 07:18:05,639 - INFO [system-artifact-loader-24:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-avro.2.11.0-SNAPSHOT. 2022-10-26 07:18:05,640 - INFO [system-artifact-loader-23:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.mmds-plugins.1.12.0-SNAPSHOT. 2022-10-26 07:18:05,642 - INFO [system-artifact-loader-40:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.mssql-plugin.1.10.0-SNAPSHOT. 2022-10-26 07:18:05,645 - INFO [system-artifact-loader-33:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.postgresql-plugin.1.10.0-SNAPSHOT. 2022-10-26 07:18:06,667 - INFO [system-artifact-loader-25:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.amazon-s3-plugins.1.19.0-SNAPSHOT. 2022-10-26 07:18:06,670 - INFO [system-artifact-loader-28:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.azure-blob-store.1.15.0-SNAPSHOT. 2022-10-26 07:18:07,686 - INFO [system-artifact-loader-26:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.hbase-plugins.2.11.0-SNAPSHOT. 2022-10-26 07:18:08,700 - INFO [system-artifact-loader-20:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.adls-plugins.1.15.0-SNAPSHOT. 2022-10-26 07:18:08,704 - INFO [system-artifact-loader-43:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.core-plugins.2.11.0-SNAPSHOT. 2022-10-26 07:18:08,710 - INFO [system-artifact-loader-38:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.kafka-plugins-client.3.2.0-SNAPSHOT. 2022-10-26 07:18:09,731 - INFO [system-artifact-loader-41:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.wrangler-transform.4.9.0-SNAPSHOT. 2022-10-26 07:18:09,733 - INFO [system-artifact-loader-29:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.format-parquet.2.11.0-SNAPSHOT. 2022-10-26 07:18:12,809 - INFO [system-artifact-loader-1:i.c.c.i.a.r.a.DefaultArtifactRepository@528] - Added system artifact artifact:system.google-cloud.0.22.0-SNAPSHOT. 2022-10-26 07:18:12,811 - DEBUG [bootstrap-service:i.c.c.i.b.e.BaseStepExecutor@66] - Bootstrap step Load system artifacts completed successfully 2022-10-26 07:18:12,820 - DEBUG [SystemAppManagementService STARTING:i.c.c.i.s.SystemAppManagementService@63] - Starting SystemAppManagementService 2022-10-26 07:18:12,820 - DEBUG [SystemProgramManagementService:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service SystemProgramManagementService 2022-10-26 07:18:12,821 - DEBUG [CapabilityManagementService:i.c.c.c.s.AbstractRetryableScheduledService@99] - Starting scheduled service CapabilityManagementService 2022-10-26 07:18:12,821 - DEBUG [SystemProgramManagementService:i.c.c.i.a.s.SystemProgramManagementService@80] - Programs to run not yet set, will be retried. 2022-10-26 07:18:12,825 - DEBUG [sys-app-management-service:i.c.c.i.s.SystemAppManagementService@77] - Number of config files 2 in system app config directory. 2022-10-26 07:18:12,825 - DEBUG [sys-app-management-service:i.c.c.i.s.SystemAppManagementService@80] - Running steps in config file /opt/cdap/master/system-app-config/..2022_10_26_07_15_54.202230683 2022-10-26 07:18:12,826 - INFO [sys-app-management-service:i.c.c.i.s.SystemAppManagementService@109] - System app config file /opt/cdap/master/system-app-config/..2022_10_26_07_15_54.202230683 does not exist. 2022-10-26 07:18:12,826 - DEBUG [sys-app-management-service:i.c.c.i.s.SystemAppManagementService@80] - Running steps in config file /opt/cdap/master/system-app-config/..data 2022-10-26 07:18:12,826 - INFO [sys-app-management-service:i.c.c.i.s.SystemAppManagementService@109] - System app config file /opt/cdap/master/system-app-config/..data does not exist. 2022-10-26 07:18:12,853 - DEBUG [CapabilityManagementService:i.c.c.i.c.CapabilityApplier@204] - Enabling capability bypass_cmek_check 2022-10-26 07:18:12,858 - DEBUG [CapabilityManagementService:i.c.c.i.c.CapabilityApplier@204] - Enabling capability pipeline 2022-10-26 07:18:12,866 - DEBUG [CapabilityManagementService:i.c.c.i.c.CapabilityApplier@308] - Application application:system.pipeline.-SNAPSHOT is being deployed 2022-10-26 07:18:12,876 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module orderedTable-leveldb to system namespace 2022-10-26 07:18:12,877 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module metricsTable-leveldb to system namespace 2022-10-26 07:18:12,877 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module core to system namespace 2022-10-26 07:18:12,881 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module fileSet to system namespace 2022-10-26 07:18:12,883 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module timePartitionedFileSet to system namespace 2022-10-26 07:18:12,884 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module partitionedFileSet to system namespace 2022-10-26 07:18:12,884 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module objectMappedTable to system namespace 2022-10-26 07:18:12,887 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module cube to system namespace 2022-10-26 07:18:12,889 - DEBUG [CapabilityManagementService:i.c.c.d.d.InMemoryDatasetFramework@134] - Adding Default module externalDataset to system namespace 2022-10-26 07:18:13,407 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_connections_store'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='createdtimemillis', type=LONG}, FieldType{name='updatedtimemillis', type=LONG}, FieldType{name='connection_id', type=STRING}, FieldType{name='connection_data', type=STRING}], primaryKeys=[namespace, generation, connection_id], indexes=[]} 2022-10-26 07:18:13,420 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_oauth'}', fieldTypes=[FieldType{name='oauthprovider', type=STRING}, FieldType{name='loginurl', type=STRING}, FieldType{name='tokenrefreshurl', type=STRING}], primaryKeys=[oauthprovider], indexes=[]} 2022-10-26 07:18:13,429 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_drafts'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='owner', type=STRING}, FieldType{name='id', type=STRING}, FieldType{name='artifact', type=STRING}, FieldType{name='name', type=STRING}, FieldType{name='description', type=STRING}, FieldType{name='createdtimemillis', type=LONG}, FieldType{name='updatedtimemillis', type=LONG}, FieldType{name='pipeline', type=STRING}, FieldType{name='revision', type=INTEGER}, FieldType{name='parentversion', type=STRING}], primaryKeys=[namespace, generation, owner, id], indexes=[]} 2022-10-26 07:18:15,172 - DEBUG [CapabilityManagementService:i.c.c.i.c.CapabilityApplier@204] - Enabling capability dataprep 2022-10-26 07:18:15,177 - DEBUG [CapabilityManagementService:i.c.c.i.c.CapabilityApplier@308] - Application application:system.dataprep.-SNAPSHOT is being deployed 2022-10-26 07:18:18,042 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_connections'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='id', type=STRING}, FieldType{name='type', type=STRING}, FieldType{name='name', type=STRING}, FieldType{name='description', type=STRING}, FieldType{name='properties', type=STRING}, FieldType{name='created', type=LONG}, FieldType{name='updated', type=LONG}, FieldType{name='preconfigured', type=STRING}], primaryKeys=[namespace, generation, id], indexes=[]} 2022-10-26 07:18:18,053 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_workspaces'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='id', type=STRING}, FieldType{name='name', type=STRING}, FieldType{name='type', type=STRING}, FieldType{name='scope', type=STRING}, FieldType{name='created', type=LONG}, FieldType{name='updated', type=LONG}, FieldType{name='properties', type=STRING}, FieldType{name='data', type=BYTES}, FieldType{name='request', type=STRING}], primaryKeys=[namespace, generation, id], indexes=[]} 2022-10-26 07:18:18,065 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_app_upgrade'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='entity_type', type=STRING}, FieldType{name='upgrade_state', type=STRING}, FieldType{name='upgrade_timestamp', type=LONG}], primaryKeys=[namespace, generation, entity_type], indexes=[]} 2022-10-26 07:18:18,075 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_schema_registry_meta'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='id', type=STRING}, FieldType{name='name', type=STRING}, FieldType{name='description', type=STRING}, FieldType{name='created', type=LONG}, FieldType{name='updated', type=LONG}, FieldType{name='type', type=STRING}, FieldType{name='auto', type=LONG}, FieldType{name='current', type=LONG}], primaryKeys=[namespace, generation, id], indexes=[]} 2022-10-26 07:18:18,084 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_schema_registry_entries'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='id', type=STRING}, FieldType{name='version', type=LONG}, FieldType{name='schema', type=BYTES}], primaryKeys=[namespace, generation, id, version], indexes=[]} 2022-10-26 07:18:18,093 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_dataprep_config'}', fieldTypes=[FieldType{name='key', type=STRING}, FieldType{name='value', type=STRING}], primaryKeys=[key], indexes=[]} 2022-10-26 07:18:18,105 - DEBUG [CapabilityManagementService:i.c.c.s.d.s.PostgreSqlStructuredTableAdmin@152] - Creating table StructuredTableSpecification{tableId='StructuredTableId{name='app_workspaces_store'}', fieldTypes=[FieldType{name='namespace', type=STRING}, FieldType{name='generation', type=LONG}, FieldType{name='workspace_id', type=STRING}, FieldType{name='createdtimemillis', type=LONG}, FieldType{name='updatedtimemillis', type=LONG}, FieldType{name='sample', type=BYTES}, FieldType{name='workspace_info', type=STRING}], primaryKeys=[namespace, generation, workspace_id], indexes=[]} 2022-10-26 07:18:20,266 - INFO [CapabilityManagementService:i.c.c.i.a.d.p.DatasetModulesDeployer@76] - Not adding dataset type 'io.cdap.cdap.api.dataset.lib.FileSet' because it is defined by the system. 2022-10-26 07:18:20,312 - INFO [CapabilityManagementService:i.c.c.i.a.d.p.DatasetInstanceCreator@74] - Adding dataset instance: dataprepfs 2022-10-26 07:18:20,326 - INFO [dataset.service-executor-2:i.c.c.d.d.d.s.DatasetInstanceService@305] - Creating dataset system.dataprepfs, type name: io.cdap.cdap.api.dataset.lib.FileSet, properties: {output.format=org.apache.hadoop.mapred.TextOutputFormat, base.path=dataprepfs/indexds, input.format=org.apache.hadoop.mapred.TextInputFormat} 2022-10-26 07:18:20,335 - DEBUG [dataset.executor-executor-0:i.c.c.d.d.d.s.e.DatasetAdminOpHTTPHandler@169] - Propagating userId as root 2022-10-26 07:18:20,336 - INFO [dataset.executor-executor-0:i.c.c.d.d.d.s.e.DatasetAdminService@92] - Creating dataset instance dataset:system.dataprepfs, type meta: DatasetTypeMeta{name='io.cdap.cdap.api.dataset.lib.FileSet', modules=[DatasetModuleMeta{name='fileSet', className='io.cdap.cdap.data2.dataset2.lib.file.FileSetModule', jarLocation=null, jarLocationPath=null, types=[io.cdap.cdap.api.dataset.lib.FileSet, fileSet], usesModules=[], usedByModules=[timePartitionedFileSet, partitionedFileSet]}]} 2022-10-26 07:18:20,339 - DEBUG [dataset.executor-executor-0:i.c.c.d.d.d.s.e.DatasetAdminService@271] - Using root user for dataset dataset:system.dataprepfs 2022-10-26 07:18:22,835 - DEBUG [SystemProgramManagementService:i.c.c.i.a.s.SystemProgramManagementService@121] - Starting program program:system.dataprep.-SNAPSHOT.service.service with args {} 2022-10-26 07:18:22,909 - DEBUG [SystemProgramManagementService:i.c.c.a.r.AbstractProgramRuntimeService@293] - Added RuntimeInfo: program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56 2022-10-26 07:18:22,911 - DEBUG [SystemProgramManagementService:i.c.c.i.a.s.SystemProgramManagementService@121] - Starting program program:system.pipeline.-SNAPSHOT.service.studio with args {} 2022-10-26 07:18:22,911 - DEBUG [program-start-0:i.c.c.i.a.d.InMemoryProgramRunDispatcher@185] - Preparing to dispatch program run: 60135721-54fe-11ed-841a-ca248ecd3c56 2022-10-26 07:18:23,020 - DEBUG [program-start-0:i.c.c.a.r.s.SparkProgramRuntimeProvider@169] - using sparkCompat SPARK3_2_12 2022-10-26 07:18:23,022 - DEBUG [SystemProgramManagementService:i.c.c.a.r.AbstractProgramRuntimeService@293] - Added RuntimeInfo: program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56 2022-10-26 07:18:23,023 - DEBUG [program-start-1:i.c.c.i.a.d.InMemoryProgramRunDispatcher@185] - Preparing to dispatch program run: 6029c552-54fe-11ed-b99a-ca248ecd3c56 2022-10-26 07:18:23,775 - DEBUG [program-start-1:i.c.c.i.a.d.InMemoryProgramRunDispatcher@574] - Plugin artifacts of program:system.pipeline.-SNAPSHOT.service.studio copied to /data/tmp/service.system.pipeline.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56 2022-10-26 07:18:24,606 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: cConf.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666768704194-0/cConf.xml} 2022-10-26 07:18:24,608 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: logback.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666768704194-0/logback.xml} 2022-10-26 07:18:24,608 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: artifacts_archive.jar LocalizeResource{archive=false, uri=file:/data/tmp/1666768704194-0/1666768704372-0/artifacts.jar} 2022-10-26 07:18:24,608 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: appSpec.json LocalizeResource{archive=false, uri=file:/data/tmp/1666768704194-0/appSpec5035295284317309436.json} 2022-10-26 07:18:24,608 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: program.jar LocalizeResource{archive=false, uri=file:/data/tmp/service.system.pipeline.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56/program.jar} 2022-10-26 07:18:24,609 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: hConf.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666768704194-0/hConf.xml} 2022-10-26 07:18:24,609 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: artifacts LocalizeResource{archive=true, uri=file:/data/tmp/1666768704194-0/1666768704372-0/artifacts.jar} 2022-10-26 07:18:24,609 - DEBUG [program-start-1:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56: program.options.json LocalizeResource{archive=false, uri=file:/data/tmp/1666768704194-0/program.options.json} 2022-10-26 07:18:24,633 - INFO [program-start-1:i.c.c.i.a.r.d.DistributedProgramRunner@591] - Starting Service Program 'studio' with Arguments [logical.start.time=1666768703012], with debugging false 2022-10-26 07:18:24,641 - DEBUG [program-start-1:i.c.c.d.u.h.HBaseVersion@244] - HBase is not available from the environment. Cannot determine HBase version. 2022-10-26 07:18:24,643 - DEBUG [program-start-1:i.c.c.i.a.r.d.DistributedProgramRunner@865] - No HBase dependencies to add. 2022-10-26 07:18:24,684 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/1666768704194-0/cConf.xml 2022-10-26 07:18:24,740 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/1666768704194-0/cConf.xml 2022-10-26 07:18:24,744 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/1666768704194-0/logback.xml 2022-10-26 07:18:24,760 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/1666768704194-0/logback.xml 2022-10-26 07:18:24,763 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/1666768704194-0/1666768704372-0/artifacts.jar 2022-10-26 07:18:25,353 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/1666768704194-0/1666768704372-0/artifacts.jar 2022-10-26 07:18:25,357 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/1666768704194-0/appSpec5035295284317309436.json 2022-10-26 07:18:25,374 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/1666768704194-0/appSpec5035295284317309436.json 2022-10-26 07:18:25,378 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/service.system.pipeline.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56/program.jar 2022-10-26 07:18:25,608 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/service.system.pipeline.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56/program.jar 2022-10-26 07:18:25,611 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/1666768704194-0/hConf.xml 2022-10-26 07:18:25,643 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/1666768704194-0/hConf.xml 2022-10-26 07:18:25,647 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/1666768704194-0/1666768704372-0/artifacts.jar 2022-10-26 07:18:26,041 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/1666768704194-0/1666768704372-0/artifacts.jar 2022-10-26 07:18:26,044 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy studio : file:/data/tmp/1666768704194-0/program.options.json 2022-10-26 07:18:26,056 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@949] - Done studio : file:/data/tmp/1666768704194-0/program.options.json 2022-10-26 07:18:26,060 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@872] - Saving twill specification for service.system.pipeline.studio to /tmp/runtime.config.jar6794717734674287118/twillSpec.json 2022-10-26 07:18:26,076 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@891] - Save twill arguments to /tmp/runtime.config.jar6794717734674287118/arguments.json 2022-10-26 07:18:26,077 - DEBUG [program-start-1:i.c.c.k.r.KubeTwillPreparer@906] - Create and upload /tmp/runtime.config.jar6794717734674287118 2022-10-26 07:18:26,119 - DEBUG [program-start-0:i.c.c.i.a.d.InMemoryProgramRunDispatcher@574] - Plugin artifacts of program:system.dataprep.-SNAPSHOT.service.service copied to /data/tmp/service.system.dataprep.service.60135721-54fe-11ed-841a-ca248ecd3c56 2022-10-26 07:18:26,128 - INFO [program-start-1:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 1.0 and memory multiplier 1.0 for program in namespace 'system' 2022-10-26 07:18:26,189 - INFO [program-start-1:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 1.0 and memory multiplier 1.0 for program in namespace 'system' 2022-10-26 07:18:26,264 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService@687] - Monitoring application service.system.pipeline.studio with run 6029c552-54fe-11ed-b99a-ca248ecd3c56 starts in 300000 MILLISECONDS 2022-10-26 07:18:26,265 - INFO [program-start-1:i.c.c.k.r.KubeTwillPreparer@756] - Created Deployment cdap-cdap-service-system-pipeline-studio-6029c552-54fe-11ed-b99a-ca248ecd3c56 in Kubernetes 2022-10-26 07:18:26,269 - DEBUG [program-start-1:i.c.c.i.a.r.d.DistributedProgramRunner@784] - Cleanup tmp files for program:system.pipeline.-SNAPSHOT.service.studio: /data/tmp/1666768704194-0 2022-10-26 07:18:26,281 - INFO [program-start-1:i.c.c.i.a.r.d.AbstractTwillProgramController@69] - Twill program running: program_run:system.pipeline.-SNAPSHOT.service.studio.6029c552-54fe-11ed-b99a-ca248ecd3c56, twill runId: 6029c552-54fe-11ed-b99a-ca248ecd3c56 2022-10-26 07:18:29,980 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: cConf.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666768708137-0/cConf.xml} 2022-10-26 07:18:29,981 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: logback.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666768708137-0/logback.xml} 2022-10-26 07:18:29,981 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: artifacts_archive.jar LocalizeResource{archive=false, uri=file:/data/tmp/1666768708137-0/1666768708216-0/artifacts.jar} 2022-10-26 07:18:29,981 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: appSpec.json LocalizeResource{archive=false, uri=file:/data/tmp/1666768708137-0/appSpec4288346240045304026.json} 2022-10-26 07:18:29,982 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: program.jar LocalizeResource{archive=false, uri=file:/data/tmp/service.system.dataprep.service.60135721-54fe-11ed-841a-ca248ecd3c56/program.jar} 2022-10-26 07:18:29,982 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: hConf.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666768708137-0/hConf.xml} 2022-10-26 07:18:29,982 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: artifacts LocalizeResource{archive=true, uri=file:/data/tmp/1666768708137-0/1666768708216-0/artifacts.jar} 2022-10-26 07:18:29,982 - DEBUG [program-start-0:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56: program.options.json LocalizeResource{archive=false, uri=file:/data/tmp/1666768708137-0/program.options.json} 2022-10-26 07:18:29,983 - INFO [program-start-0:i.c.c.i.a.r.d.DistributedProgramRunner@591] - Starting Service Program 'service' with Arguments [logical.start.time=1666768702860], with debugging false 2022-10-26 07:18:29,991 - DEBUG [program-start-0:i.c.c.d.u.h.HBaseVersion@244] - HBase is not available from the environment. Cannot determine HBase version. 2022-10-26 07:18:29,991 - DEBUG [program-start-0:i.c.c.i.a.r.d.DistributedProgramRunner@865] - No HBase dependencies to add. 2022-10-26 07:18:29,992 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/1666768708137-0/cConf.xml 2022-10-26 07:18:30,012 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/1666768708137-0/cConf.xml 2022-10-26 07:18:30,016 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/1666768708137-0/logback.xml 2022-10-26 07:18:30,031 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/1666768708137-0/logback.xml 2022-10-26 07:18:30,047 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/1666768708137-0/1666768708216-0/artifacts.jar 2022-10-26 07:18:33,736 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/1666768708137-0/1666768708216-0/artifacts.jar 2022-10-26 07:18:33,740 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/1666768708137-0/appSpec4288346240045304026.json 2022-10-26 07:18:33,755 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/1666768708137-0/appSpec4288346240045304026.json 2022-10-26 07:18:33,758 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/service.system.dataprep.service.60135721-54fe-11ed-841a-ca248ecd3c56/program.jar 2022-10-26 07:18:34,816 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/service.system.dataprep.service.60135721-54fe-11ed-841a-ca248ecd3c56/program.jar 2022-10-26 07:18:34,819 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/1666768708137-0/hConf.xml 2022-10-26 07:18:34,836 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/1666768708137-0/hConf.xml 2022-10-26 07:18:34,839 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/1666768708137-0/1666768708216-0/artifacts.jar 2022-10-26 07:18:36,094 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService$1@738] - Application service.system.pipeline.studio with run 6029c552-54fe-11ed-b99a-ca248ecd3c56 is available in Kubernetes 2022-10-26 07:18:38,079 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/1666768708137-0/1666768708216-0/artifacts.jar 2022-10-26 07:18:38,082 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy service : file:/data/tmp/1666768708137-0/program.options.json 2022-10-26 07:18:38,098 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@949] - Done service : file:/data/tmp/1666768708137-0/program.options.json 2022-10-26 07:18:38,102 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@872] - Saving twill specification for service.system.dataprep.service to /tmp/runtime.config.jar2825520376637177545/twillSpec.json 2022-10-26 07:18:38,105 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@891] - Save twill arguments to /tmp/runtime.config.jar2825520376637177545/arguments.json 2022-10-26 07:18:38,114 - DEBUG [program-start-0:i.c.c.k.r.KubeTwillPreparer@906] - Create and upload /tmp/runtime.config.jar2825520376637177545 2022-10-26 07:18:38,134 - INFO [program-start-0:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 1.0 and memory multiplier 1.0 for program in namespace 'system' 2022-10-26 07:18:38,136 - INFO [program-start-0:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 1.0 and memory multiplier 1.0 for program in namespace 'system' 2022-10-26 07:18:38,168 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService@687] - Monitoring application service.system.dataprep.service with run 60135721-54fe-11ed-841a-ca248ecd3c56 starts in 300000 MILLISECONDS 2022-10-26 07:18:38,177 - INFO [program-start-0:i.c.c.k.r.KubeTwillPreparer@756] - Created Deployment cdap-cdap-service-system-dataprep-service-60135721-54fe-11ed-841a-ca248ecd3c56 in Kubernetes 2022-10-26 07:18:38,185 - DEBUG [program-start-0:i.c.c.i.a.r.d.DistributedProgramRunner@784] - Cleanup tmp files for program:system.dataprep.-SNAPSHOT.service.service: /data/tmp/1666768708137-0 2022-10-26 07:18:38,243 - INFO [program-start-0:i.c.c.i.a.r.d.AbstractTwillProgramController@69] - Twill program running: program_run:system.dataprep.-SNAPSHOT.service.service.60135721-54fe-11ed-841a-ca248ecd3c56, twill runId: 60135721-54fe-11ed-841a-ca248ecd3c56 2022-10-26 07:18:57,299 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService$1@738] - Application service.system.dataprep.service with run 60135721-54fe-11ed-841a-ca248ecd3c56 is available in Kubernetes 2022-10-26 07:18:58,235 - ERROR [RemoteLogPublisher:i.c.c.l.a.AbstractLogPublisher@116] - Publish log message failed for RemoteLogPublisher. Will be retried. java.net.SocketTimeoutException: connect timed out at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:607) at sun.net.NetworkClient.doConnect(NetworkClient.java:175) at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) at sun.net.www.http.HttpClient.(HttpClient.java:242) at sun.net.www.http.HttpClient.New(HttpClient.java:339) at sun.net.www.http.HttpClient.New(HttpClient.java:357) at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1228) at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1162) at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1056) at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:990) at io.cdap.common.http.HttpRequests.execute(HttpRequests.java:65) at io.cdap.cdap.common.internal.remote.RemoteClient.execute(RemoteClient.java:116) at io.cdap.cdap.logging.appender.remote.RemoteLogAppender$RemoteLogPublisher.publish(RemoteLogAppender.java:153) at io.cdap.cdap.logging.appender.AbstractLogPublisher.publishMessages(AbstractLogPublisher.java:203) at io.cdap.cdap.logging.appender.AbstractLogPublisher.runTask(AbstractLogPublisher.java:107) at io.cdap.cdap.common.service.AbstractRetryableScheduledService.runOneIteration(AbstractRetryableScheduledService.java:162) at com.google.common.util.concurrent.AbstractScheduledService$1$1.run(AbstractScheduledService.java:170) at com.google.common.util.concurrent.AbstractScheduledService$CustomScheduler$ReschedulableCallable.call(AbstractScheduledService.java:355) at com.google.common.util.concurrent.AbstractScheduledService$CustomScheduler$ReschedulableCallable.call(AbstractScheduledService.java:321) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:750) 2022-10-26 07:37:49,665 - INFO [appfabric-executor-5:i.c.c.g.h.AppLifecycleHttpHandler@688] - Start to deploy app test in namespace namespace:default by user ��- 2022-10-26 07:37:53,674 - INFO [appfabric-executor-3:i.c.c.g.h.AppLifecycleHttpHandler$2@715] - Successfully deployed app test in namespace default from artifact artifact:system.cdap-data-streams.6.9.0-SNAPSHOT with configuration {"resources":{"memoryMB":2048.0,"virtualCores":1.0},"driverResources":{"memoryMB":2048.0,"virtualCores":1.0},"connections":[{"from":"HTTPPoller","to":"File"}],"comments":[],"postActions":[],"properties":{"system.spark.spark.streaming.backpressure.enabled":"true"},"processTimingEnabled":true,"stageLoggingEnabled":false,"stages":[{"name":"HTTPPoller","plugin":{"name":"HTTPPoller","type":"streamingsource","label":"HTTPPoller","artifact":{"name":"spark-plugins","version":"2.11.0-SNAPSHOT","scope":"SYSTEM"},"properties":{"referenceName":"test","url":"https://reqres.in/api/users?page\u003d2","interval":"60","charset":"UTF-8","followRedirects":"true","connectTimeout":"60000","readTimeout":"60000"}},"outputSchema":"{\"name\":\"etlSchemaBody\",\"type\":\"record\",\"fields\":[{\"name\":\"ts\",\"type\":\"long\"},{\"name\":\"url\",\"type\":\"string\"},{\"name\":\"responseCode\",\"type\":\"int\"},{\"name\":\"headers\",\"type\":{\"keys\":\"string\",\"values\":\"string\",\"type\":\"map\"}},{\"name\":\"body\",\"type\":\"string\"}]}","id":"HTTPPoller"},{"name":"File","plugin":{"name":"File","type":"batchsink","label":"File","artifact":{"name":"core-plugins","version":"2.11.0-SNAPSHOT","scope":"SYSTEM"},"properties":{"referenceName":"testf","path":"/opt","suffix":"yyyy-MM-dd-HH-mm","format":"json","schema":"{\"name\":\"etlSchemaBody\",\"type\":\"record\",\"fields\":[{\"name\":\"ts\",\"type\":\"long\"},{\"name\":\"url\",\"type\":\"string\"},{\"name\":\"responseCode\",\"type\":\"int\"},{\"name\":\"headers\",\"type\":{\"keys\":\"string\",\"values\":\"string\",\"type\":\"map\"}},{\"name\":\"body\",\"type\":\"string\"}]}"}},"outputSchema":"{\"name\":\"etlSchemaBody\",\"type\":\"record\",\"fields\":[{\"name\":\"ts\",\"type\":\"long\"},{\"name\":\"url\",\"type\":\"string\"},{\"name\":\"responseCode\",\"type\":\"int\"},{\"name\":\"headers\",\"type\":{\"keys\":\"string\",\"values\":\"string\",\"type\":\"map\"}},{\"name\":\"body\",\"type\":\"string\"}]}","inputSchema":[{"name":"HTTPPoller","schema":"{\"name\":\"etlSchemaBody\",\"type\":\"record\",\"fields\":[{\"name\":\"ts\",\"type\":\"long\"},{\"name\":\"url\",\"type\":\"string\"},{\"name\":\"responseCode\",\"type\":\"int\"},{\"name\":\"headers\",\"type\":{\"keys\":\"string\",\"values\":\"string\",\"type\":\"map\"}},{\"name\":\"body\",\"type\":\"string\"}]}"}],"id":"File"}],"batchInterval":"10s","clientResources":{"memoryMB":2048.0,"virtualCores":1.0},"disableCheckpoints":false,"checkpointDir":"","stopGracefully":true} and principal null 2022-10-26 07:37:53,941 - ERROR [appfabric-executor-13:i.c.c.c.HttpExceptionHandler@76] - Unexpected error: request=PUT /v3/namespaces/default/apps/test/schedules/dataPipelineSchedule user=: java.lang.NullPointerException: null at io.cdap.cdap.internal.app.runtime.schedule.store.Schedulers.getQuartzCronExpression(Schedulers.java:100) at io.cdap.cdap.internal.app.runtime.schedule.store.Schedulers.validateCronExpression(Schedulers.java:84) at io.cdap.cdap.internal.app.runtime.schedule.trigger.TimeTrigger.validate(TimeTrigger.java:53) at io.cdap.cdap.proto.ProtoTriggerCodec.deserialize(ProtoTriggerCodec.java:94) at io.cdap.cdap.proto.ProtoTriggerCodec.deserialize(ProtoTriggerCodec.java:35) at com.google.gson.TreeTypeAdapter.read(TreeTypeAdapter.java:58) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:103) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:196) at com.google.gson.Gson.fromJson(Gson.java:810) at com.google.gson.Gson.fromJson(Gson.java:875) at com.google.gson.Gson.fromJson(Gson.java:848) at io.cdap.cdap.gateway.handlers.ProgramLifecycleHttpHandler.readScheduleDetailBody(ProgramLifecycleHttpHandler.java:1181) at io.cdap.cdap.gateway.handlers.ProgramLifecycleHttpHandler.doAddSchedule(ProgramLifecycleHttpHandler.java:1101) at io.cdap.cdap.gateway.handlers.ProgramLifecycleHttpHandler.addSchedule(ProgramLifecycleHttpHandler.java:1081) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at io.cdap.http.internal.HttpMethodInfo.invoke(HttpMethodInfo.java:87) at io.cdap.http.internal.HttpDispatcher.channelRead(HttpDispatcher.java:45) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:38) at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:353) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) at io.cdap.http.internal.NonStickyEventExecutorGroup$NonStickyOrderedEventExecutor.run(NonStickyEventExecutorGroup.java:254) at io.netty.util.concurrent.UnorderedThreadPoolEventExecutor$NonNotifyRunnable.run(UnorderedThreadPoolEventExecutor.java:277) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:750) 2022-10-26 07:38:06,997 - INFO [appfabric-executor-18:i.c.c.i.a.s.RunRecordMonitorService@139] - Added request with runId program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56. 2022-10-26 07:38:06,998 - INFO [appfabric-executor-18:i.c.c.i.a.s.RunRecordMonitorService@127] - Counter has 1 concurrent launching and 0 running programs. 2022-10-26 07:38:07,000 - INFO [appfabric-executor-18:i.c.c.i.a.s.ProgramLifecycleService@561] - Attempt to run Spark program DataStreamsSparkStreaming as user with arguments {logical.start.time=1666769886989} 2022-10-26 07:38:07,549 - DEBUG [program.status:i.c.c.i.p.t.ProvisioningTask@87] - Created PROVISION task for program run program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56. 2022-10-26 07:38:07,564 - DEBUG [provisioning-task-0:i.c.c.i.p.t.ProvisioningTask@126] - Executing PROVISION subtask REQUESTING_CREATE for program run program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56. 2022-10-26 07:38:07,566 - DEBUG [provisioning-task-0:i.c.c.i.p.t.ProvisioningTask@130] - Completed PROVISION subtask REQUESTING_CREATE for program run program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56. 2022-10-26 07:38:07,583 - DEBUG [provisioning-task-0:i.c.c.i.p.t.ProvisioningTask@117] - Completed PROVISION task for program run program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56. 2022-10-26 07:38:09,584 - WARN [program.status:i.c.c.i.a.r.d.DistributedProgramRuntimeService@147] - Twill RunId does not exist for the program program:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming, runId 21de2bd4-5501-11ed-82a8-ca248ecd3c56 2022-10-26 07:38:09,584 - DEBUG [program.status:i.c.c.a.r.AbstractProgramRuntimeService@293] - Added RuntimeInfo: program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56 2022-10-26 07:38:09,585 - DEBUG [program-start-2:i.c.c.i.a.d.InMemoryProgramRunDispatcher@185] - Preparing to dispatch program run: 21de2bd4-5501-11ed-82a8-ca248ecd3c56 2022-10-26 07:38:09,585 - DEBUG [program-start-2:i.c.c.a.r.s.SparkProgramRuntimeProvider@169] - using sparkCompat SPARK3_2_12 2022-10-26 07:38:09,652 - DEBUG [program-start-2:i.c.c.a.r.s.SparkPackageUtils@317] - Located Spark library in in /opt/spark/spark-3.1.1-bin-without-hadoop/jars 2022-10-26 07:38:11,923 - DEBUG [program-start-2:i.c.c.i.a.d.InMemoryProgramRunDispatcher@574] - Plugin artifacts of program:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming copied to /data/tmp/spark.default.test.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56 2022-10-26 07:38:12,172 - DEBUG [program-start-2:i.c.c.a.r.s.SparkPackageUtils@566] - Skip reading {} for Spark environment due to unreadable file 2022-10-26 07:38:12,176 - DEBUG [program-start-2:i.c.c.a.r.s.SparkPackageUtils@317] - Located Spark library in in /opt/spark/spark-3.1.1-bin-without-hadoop/jars 2022-10-26 07:38:15,257 - DEBUG [program-start-2:i.c.c.a.r.s.SparkPackageUtils@259] - Adding files from /opt/hadoop/hadoop-2.9.2/etc/hadoop to __spark_conf__.zip 2022-10-26 07:38:15,663 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: pyspark.zip LocalizeResource{archive=false, uri=file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/pyspark.zip} 2022-10-26 07:38:15,663 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: logback.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666769892165-0/logback.xml} 2022-10-26 07:38:15,664 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: __spark_conf__ LocalizeResource{archive=true, uri=file:/data/tmp/1666769892165-0/__spark_conf__9147552778953842179.zip} 2022-10-26 07:38:15,664 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: appSpec.json LocalizeResource{archive=false, uri=file:/data/tmp/1666769892165-0/appSpec5177301890436214358.json} 2022-10-26 07:38:15,664 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: hConf.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666769892165-0/hConf.xml} 2022-10-26 07:38:15,664 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: program.options.json LocalizeResource{archive=false, uri=file:/data/tmp/1666769892165-0/program.options.json} 2022-10-26 07:38:15,664 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: cConf.xml LocalizeResource{archive=false, uri=file:/data/tmp/1666769892165-0/cConf.xml} 2022-10-26 07:38:15,665 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: artifacts_archive.jar LocalizeResource{archive=false, uri=file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar} 2022-10-26 07:38:15,665 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: spark-defaults.conf LocalizeResource{archive=false, uri=file:/data/tmp/1666769892165-0/spark-defaults.conf3504512643549673422.tmp} 2022-10-26 07:38:15,665 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: program.jar LocalizeResource{archive=false, uri=file:/data/tmp/spark.default.test.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56/program.jar} 2022-10-26 07:38:15,665 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: spark.archive-spark3_2.12-2.9.2.zip LocalizeResource{archive=true, uri=hdfs://hadoop:9000/cdap/framework/spark/spark.archive-spark3_2.12-2.9.2.zip} 2022-10-26 07:38:15,665 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: py4j-0.10.9-src.zip LocalizeResource{archive=false, uri=file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/py4j-0.10.9-src.zip} 2022-10-26 07:38:15,665 - DEBUG [program-start-2:i.c.c.i.a.r.d.ProgramTwillApplication@127] - Localizing file for program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56: artifacts LocalizeResource{archive=true, uri=file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar} 2022-10-26 07:38:15,666 - INFO [program-start-2:i.c.c.i.a.r.d.DistributedProgramRunner@591] - Starting Spark Program 'DataStreamsSparkStreaming' with Arguments [logical.start.time=1666769886989], with debugging false 2022-10-26 07:38:15,668 - DEBUG [program-start-2:i.c.c.d.u.h.HBaseVersion@244] - HBase is not available from the environment. Cannot determine HBase version. 2022-10-26 07:38:15,668 - DEBUG [program-start-2:i.c.c.i.a.r.d.DistributedProgramRunner@865] - No HBase dependencies to add. 2022-10-26 07:38:15,669 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/pyspark.zip 2022-10-26 07:38:15,702 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/pyspark.zip 2022-10-26 07:38:15,705 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/logback.xml 2022-10-26 07:38:15,720 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/logback.xml 2022-10-26 07:38:15,723 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/__spark_conf__9147552778953842179.zip 2022-10-26 07:38:15,737 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/__spark_conf__9147552778953842179.zip 2022-10-26 07:38:15,739 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/appSpec5177301890436214358.json 2022-10-26 07:38:15,753 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/appSpec5177301890436214358.json 2022-10-26 07:38:15,756 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/hConf.xml 2022-10-26 07:38:15,771 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/hConf.xml 2022-10-26 07:38:15,773 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/program.options.json 2022-10-26 07:38:15,786 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/program.options.json 2022-10-26 07:38:15,789 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/cConf.xml 2022-10-26 07:38:15,803 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/cConf.xml 2022-10-26 07:38:15,806 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:16,590 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:16,593 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/spark-defaults.conf3504512643549673422.tmp 2022-10-26 07:38:16,607 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/spark-defaults.conf3504512643549673422.tmp 2022-10-26 07:38:16,610 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/spark.default.test.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56/program.jar 2022-10-26 07:38:16,764 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/spark.default.test.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56/program.jar 2022-10-26 07:38:16,769 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/py4j-0.10.9-src.zip 2022-10-26 07:38:16,783 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/opt/spark/spark-3.1.1-bin-without-hadoop/python/lib/py4j-0.10.9-src.zip 2022-10-26 07:38:16,786 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@946] - Create and copy DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:17,550 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@949] - Done DataStreamsSparkStreaming : file:/data/tmp/1666769892165-0/1666769895298-0/artifacts.jar 2022-10-26 07:38:17,553 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@872] - Saving twill specification for spark.default.test.DataStreamsSparkStreaming to /tmp/runtime.config.jar5829944738190464809/twillSpec.json 2022-10-26 07:38:17,556 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@891] - Save twill arguments to /tmp/runtime.config.jar5829944738190464809/arguments.json 2022-10-26 07:38:17,557 - DEBUG [program-start-2:i.c.c.k.r.KubeTwillPreparer@906] - Create and upload /tmp/runtime.config.jar5829944738190464809 2022-10-26 07:38:17,571 - INFO [program-start-2:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 0.5 and memory multiplier 0.5 for program in namespace 'default' 2022-10-26 07:38:17,572 - INFO [program-start-2:i.c.c.k.r.KubeTwillPreparer@1229] - Using CPU multiplier 0.5 and memory multiplier 0.5 for program in namespace 'default' 2022-10-26 07:38:17,613 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService@687] - Monitoring application spark.default.test.DataStreamsSparkStreaming with run 21de2bd4-5501-11ed-82a8-ca248ecd3c56 starts in 300000 MILLISECONDS 2022-10-26 07:38:17,620 - INFO [program-start-2:i.c.c.k.r.KubeTwillPreparer@756] - Created Deployment cdap-cdap-spark-default-test-datastreamssparkstreaming-21de2bd4-5501-11ed-82a8-ca248ecd3c56 in Kubernetes 2022-10-26 07:38:17,620 - DEBUG [program-start-2:i.c.c.i.a.r.d.DistributedProgramRunner@784] - Cleanup tmp files for program:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming: /data/tmp/1666769892165-0 2022-10-26 07:38:17,633 - INFO [program-start-2:i.c.c.i.a.r.d.AbstractTwillProgramController@69] - Twill program running: program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56, twill runId: 21de2bd4-5501-11ed-82a8-ca248ecd3c56 2022-10-26 07:38:19,590 - INFO [program.status:i.c.c.i.a.s.RunRecordMonitorService@151] - Removed request with runId program_run:default.test.178a9603-5501-11ed-921a-ca248ecd3c56.spark.DataStreamsSparkStreaming.21de2bd4-5501-11ed-82a8-ca248ecd3c56. Counter has 0 concurrent launching requests. 2022-10-26 07:38:34,900 - DEBUG [kube-deployments-watch:i.c.c.k.r.KubeTwillRunnerService$1@738] - Application spark.default.test.DataStreamsSparkStreaming with run 21de2bd4-5501-11ed-82a8-ca248ecd3c56 is available in Kubernetes [root@ip-172-31-30-183 cdap-operator]#