You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@livy.apache.org by "Kupersanin, William" <ku...@mitre.org> on 2019/08/26 20:49:50 UTC
Java Null Pointer exception when session starts.
Hello,
I just built livy-0.7.0-incubating from the master branch on github. I am trying to establish a session using jupyter/sparkmagic. It's failing. The jupyter client thinks that the session is not starting in time though the livy logs indicate that it is. The livy logs include a java exception included below but I am not sure why. Yarn creates the session and I can view it in the web ui.
Pointers are greatly appreciated.
Thanks,
--Willie
Livy server log as follows
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO client.RMProxy: Connecting to ResourceManager at devs.mitre.org/10.10.0.2:8032
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO yarn.Client: Requesting a new application from cluster with 1 NodeManagers
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO yarn.Client: Verifying our application has not requested more than the maximum memory capability of the cluster (82339 MB per container)
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO yarn.Client: Will allocate AM container, with 896 MB memory including 384 MB overhead
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO yarn.Client: Setting up container launch context for our AM
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO yarn.Client: Setting up the launch environment for our AM container
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO yarn.Client: Preparing resources for our AM container
19/08/26 16:24:46 INFO LineBufferedStream: 19/08/26 16:24:46 INFO yarn.Client: Uploading resource file:/usr/local/livy/rsc/target/jars/unused-1.0.0.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/unused-1.0.0.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/rsc/target/jars/livy-api-0.7.0-incubating-SNAPSHOT.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/livy-api-0.7.0-incubating-SNAPSHOT.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/rsc/target/jars/netty-all-4.0.37.Final.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/netty-all-4.0.37.Final.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/rsc/target/jars/scala-library-2.11.12.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/scala-library-2.11.12.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/rsc/target/jars/spark-tags_2.11-2.2.0.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/spark-tags_2.11-2.2.0.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/rsc/target/jars/livy-rsc-0.7.0-incubating-SNAPSHOT.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/livy-rsc-0.7.0-incubating-SNAPSHOT.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/repl/scala-2.11/target/jars/livy-core_2.11-0.7.0-incubating-SNAPSHOT.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/livy-core_2.11-0.7.0-incubating-SNAPSHOT.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/repl/scala-2.11/target/jars/commons-codec-1.9.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/commons-codec-1.9.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/usr/local/livy/repl/scala-2.11/target/jars/livy-repl_2.11-0.7.0-incubating-SNAPSHOT.jar -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/livy-repl_2.11-0.7.0-incubating-SNAPSHOT.jar
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/opt/cloudera/parcels/SPARK2/lib/spark2/python/lib/pyspark.zip -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/pyspark.zip
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/opt/cloudera/parcels/SPARK2/lib/spark2/python/lib/py4j-0.10.7-src.zip -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/py4j-0.10.7-src.zip
19/08/26 16:24:47 INFO LineBufferedStream: 19/08/26 16:24:47 INFO yarn.Client: Uploading resource file:/tmp/spark-3d78104f-9211-4e1b-9dd8-9559a942fbbb/__spark_conf__6043890608672430821.zip -> hdfs://devs.mitre.org:8020/user/root/.sparkStaging/application_1566848095304_0004/__spark_conf__.zip
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO spark.SecurityManager: Changing view acls to: root
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO spark.SecurityManager: Changing modify acls to: root
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO spark.SecurityManager: Changing view acls groups to:
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO spark.SecurityManager: Changing modify acls groups to:
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(root); groups with view permissions: Set(); users with modify permissions: Set(root); groups with modify permissions: Set()
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO yarn.Client: Submitting application application_1566848095304_0004 to ResourceManager
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO impl.YarnClientImpl: Submitted application application_1566848095304_0004
19/08/26 16:24:48 INFO LineBufferedStream: 19/08/26 16:24:48 INFO cluster.SchedulerExtensionServices: Starting Yarn extension services with app application_1566848095304_0004 and attemptId None
19/08/26 16:24:49 INFO LineBufferedStream: 19/08/26 16:24:49 INFO yarn.Client: Application report for application_1566848095304_0004 (state: ACCEPTED)
19/08/26 16:24:49 INFO LineBufferedStream: 19/08/26 16:24:49 INFO yarn.Client:
19/08/26 16:24:49 INFO LineBufferedStream: client token: N/A
19/08/26 16:24:52 INFO LineBufferedStream: diagnostics: N/A
19/08/26 16:24:52 INFO LineBufferedStream: ApplicationMaster host: 10.10.0.3
19/08/26 16:24:52 INFO LineBufferedStream: ApplicationMaster RPC port: -1
19/08/26 16:24:52 INFO LineBufferedStream: queue: root.users.root
19/08/26 16:24:52 INFO LineBufferedStream: start time: 1566851088710
19/08/26 16:24:52 INFO LineBufferedStream: final status: UNDEFINED
19/08/26 16:24:52 INFO LineBufferedStream: tracking URL: http://devs.mitre.org:8088/proxy/application_1566848095304_0004/
19/08/26 16:24:52 INFO LineBufferedStream: user: root
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO cluster.YarnClientSchedulerBackend: Application application_1566848095304_0004 has started running.
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO util.Utils: max retries is 16
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 37876.
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO netty.NettyBlockTransferService: Server created on devs.mitre.org:37876
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO storage.BlockManager: Using org.apache.spark.storage.RandomBlockReplicationPolicy for block replication policy
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO storage.BlockManagerMaster: Registering BlockManager BlockManagerId(driver, devs.mitre.org, 37876, None)
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO storage.BlockManagerMasterEndpoint: Registering block manager devs.mitre.org:37876 with 2004.6 MB RAM, BlockManagerId(driver, devs.mitre.org, 37876, None)
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO storage.BlockManagerMaster: Registered BlockManager BlockManagerId(driver, devs.mitre.org, 37876, None)
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO storage.BlockManager: external shuffle service port = 7337
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO storage.BlockManager: Initialized BlockManager: BlockManagerId(driver, devs.mitre.org, 37876, None)
19/08/26 16:24:52 INFO LineBufferedStream: 19/08/26 16:24:52 INFO cluster.YarnSchedulerBackend$YarnSchedulerEndpoint: ApplicationMaster registered as NettyRpcEndpointRef(spark-client://YarnAM)
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO ui.JettyUtils: Adding filter org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter to /metrics/json.
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO handler.ContextHandler: Started o.s.j.s.ServletContextHandler@6e287cb7{/metrics/json,null,AVAILABLE,@Spark}
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO scheduler.EventLoggingListener: Logging events to hdfs://devs.mitre.org:8020/user/spark/spark2ApplicationHistory/application_1566848095304_0004
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO util.Utils: Using initial executors = 0, max of spark.dynamicAllocation.initialExecutors, spark.dynamicAllocation.minExecutors and spark.executor.instances
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 WARN lineage.LineageWriter: Lineage directory /var/log/spark2/lineage doesn't exist or is not writable. Lineage for this application will be disabled.
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO util.Utils: Extension com.cloudera.spark.lineage.NavigatorAppListener not being initialized.
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO cluster.YarnClientSchedulerBackend: SchedulerBackend is ready for scheduling beginning after reached minRegisteredResourcesRatio: 0.8
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO driver.SparkEntries: Spark context finished initialization in 7932ms
19/08/26 16:24:53 INFO LineBufferedStream: 19/08/26 16:24:53 INFO driver.SparkEntries: Created Spark session.
19/08/26 16:24:53 INFO LineBufferedStream: Exception in thread "main" java.lang.NullPointerException
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.livy.rsc.driver.JobWrapper.cancel(JobWrapper.java:90)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.livy.rsc.driver.RSCDriver.shutdown(RSCDriver.java:127)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.livy.rsc.driver.RSCDriver.run(RSCDriver.java:356)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.livy.rsc.driver.RSCDriverBootstrapper.main(RSCDriverBootstrapper.java:93)
19/08/26 16:24:53 INFO LineBufferedStream: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
19/08/26 16:24:53 INFO LineBufferedStream: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
19/08/26 16:24:53 INFO LineBufferedStream: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
19/08/26 16:24:53 INFO LineBufferedStream: at java.lang.reflect.Method.invoke(Method.java:498)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.JavaMainApplication.start(SparkApplication.scala:52)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.SparkSubmit.org$apache$spark$deploy$SparkSubmit$$runMain(SparkSubmit.scala:849)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.SparkSubmit.doRunMain$1(SparkSubmit.scala:167)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.SparkSubmit.submit(SparkSubmit.scala:195)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.SparkSubmit.doSubmit(SparkSubmit.scala:86)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.SparkSubmit$$anon$2.doSubmit(SparkSubmit.scala:924)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.SparkSubmit$.main(SparkSubmit.scala:933)
19/08/26 16:24:53 INFO LineBufferedStream: at org.apache.spark.deploy.SparkSubmit.main(SparkSubmit.scala)
Yarn Log
2019-08-26 16:24:46,764 INFO org.apache.hadoop.yarn.server.resourcemanager.ClientRMService: Allocated new applicationId: 4
2019-08-26 16:24:48,710 INFO org.apache.hadoop.yarn.server.resourcemanager.ClientRMService: Application with id 4 submitted by user root
2019-08-26 16:24:48,711 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppImpl: Storing application with id application_1566848095304_0004
2019-08-26 16:24:48,711 INFO org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=root IP=10.10.0.2 OPERATION=Submit Application Request TARGET=ClientRMService RESULT=SUCCESS APPID=application_1566848095304_0004
2019-08-26 16:24:48,711 INFO org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore: Storing info for app: application_1566848095304_0004
2019-08-26 16:24:48,711 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppImpl: application_1566848095304_0004 State change from NEW to NEW_SAVING on event = START
2019-08-26 16:24:48,711 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppImpl: application_1566848095304_0004 State change from NEW_SAVING to SUBMITTED on event = APP_NEW_SAVED
2019-08-26 16:24:48,711 INFO org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler: Accepted application application_1566848095304_0004 from user: root, in queue: root.users.root, currently num of applications: 1
2019-08-26 16:24:48,712 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppImpl: application_1566848095304_0004 State change from SUBMITTED to ACCEPTED on event = APP_ACCEPTED
2019-08-26 16:24:48,712 INFO org.apache.hadoop.yarn.server.resourcemanager.ApplicationMasterService: Registering app attempt : appattempt_1566848095304_0004_000001
2019-08-26 16:24:48,712 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: appattempt_1566848095304_0004_000001 State change from NEW to SUBMITTED on event = START
2019-08-26 16:24:48,712 INFO org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler: Added Application Attempt appattempt_1566848095304_0004_000001 to scheduler from user: root
2019-08-26 16:24:48,713 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: appattempt_1566848095304_0004_000001 State change from SUBMITTED to SCHEDULED on event = ATTEMPT_ADDED
2019-08-26 16:24:48,851 INFO org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl: container_1566848095304_0004_01_000001 Container Transitioned from NEW to ALLOCATED
2019-08-26 16:24:48,851 INFO org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=root OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1566848095304_0004 CONTAINERID=container_1566848095304_0004_01_000001
2019-08-26 16:24:48,851 INFO org.apache.hadoop.yarn.server.resourcemanager.scheduler.SchedulerNode: Assigned container container_1566848095304_0004_01_000001 of capacity <memory:1024, vCores:1> on host devs2.mitre.org:8041, which has 1 containers, <memory:1024, vCores:1> used and <memory:81315, vCores:47> available after allocation
2019-08-26 16:24:48,851 INFO org.apache.hadoop.yarn.server.resourcemanager.security.NMTokenSecretManagerInRM: Sending NMToken for nodeId : devs2.mitre.org:8041 for container : container_1566848095304_0004_01_000001
2019-08-26 16:24:48,852 INFO org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl: container_1566848095304_0004_01_000001 Container Transitioned from ALLOCATED to ACQUIRED
2019-08-26 16:24:48,852 INFO org.apache.hadoop.yarn.server.resourcemanager.security.NMTokenSecretManagerInRM: Clear node set for appattempt_1566848095304_0004_000001
2019-08-26 16:24:48,852 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: Storing attempt: AppId: application_1566848095304_0004 AttemptId: appattempt_1566848095304_0004_000001 MasterContainer: Container: [ContainerId: container_1566848095304_0004_01_000001, NodeId: devs2.mitre.org:8041, NodeHttpAddress: devs2.mitre.org:8042, Resource: <memory:1024, vCores:1>, Priority: 0, Token: Token { kind: ContainerToken, service: 10.10.0.3:8041 }, ]
2019-08-26 16:24:48,853 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: appattempt_1566848095304_0004_000001 State change from SCHEDULED to ALLOCATED_SAVING on event = CONTAINER_ALLOCATED
2019-08-26 16:24:48,853 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: appattempt_1566848095304_0004_000001 State change from ALLOCATED_SAVING to ALLOCATED on event = ATTEMPT_NEW_SAVED
2019-08-26 16:24:48,854 INFO org.apache.hadoop.yarn.server.resourcemanager.amlauncher.AMLauncher: Launching masterappattempt_1566848095304_0004_000001
2019-08-26 16:24:48,857 INFO org.apache.hadoop.yarn.server.resourcemanager.amlauncher.AMLauncher: Setting up container Container: [ContainerId: container_1566848095304_0004_01_000001, NodeId: devs2.mitre.org:8041, NodeHttpAddress: devs2.mitre.org:8042, Resource: <memory:1024, vCores:1>, Priority: 0, Token: Token { kind: ContainerToken, service: 10.10.0.3:8041 }, ] for AM appattempt_1566848095304_0004_000001
2019-08-26 16:24:48,857 INFO org.apache.hadoop.yarn.server.resourcemanager.security.AMRMTokenSecretManager: Create AMRMToken for ApplicationAttempt: appattempt_1566848095304_0004_000001
2019-08-26 16:24:48,857 INFO org.apache.hadoop.yarn.server.resourcemanager.security.AMRMTokenSecretManager: Creating password for appattempt_1566848095304_0004_000001
2019-08-26 16:24:48,872 INFO org.apache.hadoop.yarn.server.resourcemanager.amlauncher.AMLauncher: Done launching container Container: [ContainerId: container_1566848095304_0004_01_000001, NodeId: devs2.mitre.org:8041, NodeHttpAddress: devs2.mitre.org:8042, Resource: <memory:1024, vCores:1>, Priority: 0, Token: Token { kind: ContainerToken, service: 10.10.0.3:8041 }, ] for AM appattempt_1566848095304_0004_000001
2019-08-26 16:24:48,872 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: appattempt_1566848095304_0004_000001 State change from ALLOCATED to LAUNCHED on event = LAUNCHED
2019-08-26 16:24:49,851 INFO org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl: container_1566848095304_0004_01_000001 Container Transitioned from ACQUIRED to RUNNING
2019-08-26 16:24:52,469 INFO org.apache.hadoop.yarn.server.resourcemanager.ApplicationMasterService: AM registration appattempt_1566848095304_0004_000001
2019-08-26 16:24:52,469 INFO org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=root IP=10.10.0.3 OPERATION=Register App Master TARGET=ApplicationMasterService RESULT=SUCCESS APPID=application_1566848095304_0004 APPATTEMPTID=appattempt_1566848095304_0004_000001
2019-08-26 16:24:52,469 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: appattempt_1566848095304_0004_000001 State change from LAUNCHED to RUNNING on event = REGISTERED
2019-08-26 16:24:52,470 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppImpl: application_1566848095304_0004 State change from ACCEPTED to RUNNING on event = ATTEMPT_REGISTERED