> For the complete documentation index, see [llms.txt](https://knowledge-learn.gitbook.io/yarn/llms.txt). Markdown versions of documentation pages are available by appending `.md` to page URLs; this page is available as [Markdown](https://knowledge-learn.gitbook.io/yarn/qa/app-failed-rm-exit.md). # 集群繁忙时偶发性空指针导致app执行失败 放在最前面：该问题是社区已知的缺陷，更多参考：。本文主要介绍问题定位思路和分析过程。 ## 1. 问题描述 app执行日志中异常堆栈如下： ![](/files/-MWNuTTNMAAndU8-WBy-) 从字面意思理解就是AM启动之后向RM注册异常，然后失败了。 通过进一步的了解，我们知道yarn 集群最近做了扩容，app 提交规模也上来了。而且有部分app成功，有部分失败。失败app原因都是如上截图所示，没有明显的node 关联性。 ## 2. 问题分析 ### 2.1 确认异常位置 从异常堆栈，我们看到是AM向RM注册的过程中，抛出空指针异常导致app异常退出。也就是说不是am 本身的代码逻辑出现空指针，而是RPC调用返回了空指针。进一步说就是RM在处理过程中出现空指针。 我们通过搜索RM日志，并没有相关时间范围内发现有异常信息。 现在我们走到了一个死胡同，我们知道是RM在处理AM注册请求时出现空指针异常，但是在RM日志中找不到异常信息，而且AM异常堆栈中没有打印RM空指针出现的行号。 ### 2.2 RM 日志分析 进一步RM日志，我们观察到一个异常信息 ``` attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:rememberTargetTransitionsAndStoreState(1165)) - Updating application attempt appattempt_1616059928557_55186_000002 with final state: FAILED, and exit status: 1 ``` 这个异常是说AM执行异常了，退出码为1（其实也容易理解，AM向RM注册异常，尝试几次之后，告诉RM我执行不下去了，我要异常退出）。 所以回到RM日志，我们重新梳理了RM处理AM注册部分的逻辑。 重点看如下日志（通过appid 关键字过滤） ``` 2021-03-20 19:13:52,261 INFO attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(796)) - appattempt_1616059928557_55186_000001 State change from ALLOCATED_SAVING to ALLOCATED 2021-03-20 19:14:04,020 INFO amlauncher.AMLauncher (AMLauncher.java:run(249)) - Launching masterappattempt_1616059928557_55186_000001 2021-03-20 19:14:04,020 INFO amlauncher.AMLauncher (AMLauncher.java:launch(105)) - Setting up container Container: [ContainerId: container_e10_1616059928557_55186_01_000001, NodeId: tbds-172-29-15-181:45454, NodeHttpAddress: tbds-172-29-15-181:8042, Resource: , Priority: 0, Token: Token { kind: ContainerToken, service: 172.29.15.181:45454 }, ] for AM appattempt_1616059928557_55186_000001 2021-03-20 19:14:04,020 INFO amlauncher.AMLauncher (AMLauncher.java:createAMContainerLaunchContext(187)) - Command to launch container container_e10_1616059928557_55186_01_000001 : $JAVA_HOME/bin/java -Djava.io.tmpdir=$PWD/tmp -Dlog4j.configuration=container-log4j.properties -Dyarn.app.container.log.dir= -Dyarn.app.container.log.filesize=0 -Dhadoop.root.logger=INFO,CLA -Dhadoop.root.logfile=syslog -Dhdp.version=2.2.0.0-2041 -Xmx3072m org.apache.hadoop.mapreduce.v2.app.MRAppMaster 1>/stdout 2>/stderr 2021-03-20 19:14:04,020 INFO security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:createAndGetAMRMToken(195)) - Create AMRMToken for ApplicationAttempt: appattempt_1616059928557_55186_000001 2021-03-20 19:14:04,020 INFO security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:createPassword(307)) - Creating password for appattempt_1616059928557_55186_000001 2021-03-20 19:14:04,023 INFO amlauncher.AMLauncher (AMLauncher.java:launch(126)) - Done launching container Container: [ContainerId: container_e10_1616059928557_55186_01_000001, NodeId: tbds-172-29-15-181:45454, NodeHttpAddress: tbds-172-29-15-181:8042, Resource: , Priority: 0, Token: Token { kind: ContainerToken, service: 172.29.15.181:45454 }, ] for AM appattempt_1616059928557_55186_000001 2021-03-20 19:14:09,528 INFO ipc.Server (Server.java:saslProcess(1316)) - Auth successful for appattempt_1616059928557_55186_000001 (auth:SIMPLE) 2021-03-20 19:14:09,530 INFO resourcemanager.ApplicationMasterService (ApplicationMasterService.java:registerApplicationMaster(274)) - AM registration appattempt_1616059928557_55186_000001 2021-03-20 19:14:09,530 INFO resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(127)) - USER=tdwhive IP=172.29.15.181 OPERATION=Register App Master TARGET=ApplicationMasterService RESULT=SUCCESS APPID=application_1616059928557_55186 APPATTEMPTID=appattempt_1616059928557_55186_000001 2021-03-20 19:14:16,977 INFO attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(796)) - appattempt_1616059928557_55186_000001 State change from ALLOCATED to LAUNCHED 2021-03-20 19:14:22,670 INFO attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(796)) - appattempt_1616059928557_55186_000001 State change from LAUNCHED to RUNNING 2021-03-20 19:14:22,671 INFO rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(410)) - container_e10_1616059928557_55186_01_000001 Container Transitioned from ACQUIRED to RUNNING 2021-03-20 19:14:31,376 INFO rmapp.RMAppImpl (RMAppImpl.java:handle(715)) - application_1616059928557_55186 State change from ACCEPTED to RUNNING 2021-03-20 19:14:31,659 INFO rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(410)) - container_e10_1616059928557_55186_01_000001 Container Transitioned from RUNNING to COMPLETED ``` 结合下图（RMAppAttempt 状态流转图，[完整图](https://www.processon.com/view/link/5d10d751e4b024123de6bd47)），我们来分析在AM启动之后，向RM注册过程，会涉及到RMAppAttempt 对象从Allocated到running状态到变化。 ![](/files/-MWO16BuQzCPIoU97Jby) 我们19:14:04,023 看到日志关键字： Done launching 。说明AM已经被发送到NodeManager 。然后接下来第二行日志 （也就是19:14:09）我们看到日志关键字：AM registration 。这就是说在 14分04秒RM下发完成，14分09秒AM就来注册了。接下来神奇的事情发生了，也就是再下面第二行（也就是19:14:16）我们看到RMAppAttempt 状态变化了（change from ALLOCATED to LAUNCHED）。 我们比较一个成功的app 对应的RM处理日志，则没有上面描述的问题 ``` 2021-03-22 10:51:17,048 INFO amlauncher.AMLauncher (AMLauncher.java:run(249)) - Launching masterappattempt_1616340089879_4264_000001 2021-03-22 10:51:17,048 INFO amlauncher.AMLauncher (AMLauncher.java:launch(105)) - Setting up container Container: [ContainerId: container_e12_1616340089879_4264_01_000001, NodeId: tbds-172-29-0-125:45454, NodeHttpAddress: tbds-172-29-0-125:8042, Resource: , Priority: 0, Token: Token { kind: ContainerToken, service: 172.29.0.125:45454 }, ] for AM appattempt_1616340089879_4264_000001 2021-03-22 10:51:17,048 INFO amlauncher.AMLauncher (AMLauncher.java:createAMContainerLaunchContext(187)) - Command to launch container container_e12_1616340089879_4264_01_000001 : $JAVA_HOME/bin/java -Djava.io.tmpdir=$PWD/tmp -Dlog4j.configuration=container-log4j.properties -Dyarn.app.container.log.dir= -Dyarn.app.container.log.filesize=0 -Dhadoop.root.logger=INFO,CLA -Dhadoop.root.logfile=syslog -Dhdp.version=2.2.0.0-2041 -Xmx3072m org.apache.hadoop.mapreduce.v2.app.MRAppMaster 1>/stdout 2>/stderr 2021-03-22 10:51:17,048 INFO security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:createAndGetAMRMToken(195)) - Create AMRMToken for ApplicationAttempt: appattempt_1616340089879_4264_000001 2021-03-22 10:51:17,048 INFO security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:createPassword(307)) - Creating password for appattempt_1616340089879_4264_000001 2021-03-22 10:51:17,052 INFO amlauncher.AMLauncher (AMLauncher.java:launch(126)) - Done launching container Container: [ContainerId: container_e12_1616340089879_4264_01_000001, NodeId: tbds-172-29-0-125:45454, NodeHttpAddress: tbds-172-29-0-125:8042, Resource: , Priority: 0, Token: Token { kind: ContainerToken, service: 172.29.0.125:45454 }, ] for AM appattempt_1616340089879_4264_000001 2021-03-22 10:51:17,052 INFO attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(796)) - appattempt_1616340089879_4264_000001 State change from ALLOCATED to LAUNCHED 2021-03-22 10:51:17,677 INFO rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(410)) - container_e12_1616340089879_4264_01_000001 Container Transitioned from ACQUIRED to RUNNING 2021-03-22 10:51:22,251 INFO ipc.Server (Server.java:saslProcess(1316)) - Auth successful for appattempt_1616340089879_4264_000001 (auth:SIMPLE) 2021-03-22 10:51:22,253 INFO resourcemanager.ApplicationMasterService (ApplicationMasterService.java:registerApplicationMaster(274)) - AM registration appattempt_1616340089879_4264_000001 2021-03-22 10:51:22,253 INFO resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(127)) - USER=tdwhive IP=172.29.0.125 OPERATION=Register App Master TARGET=ApplicationMasterService RESULT=SUCCESS APPID=application_1616340089879_4264 APPATTEMPTID=appattempt_1616340089879_4264_000001 2021-03-22 10:51:22,253 INFO attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(796)) - appattempt_1616340089879_4264_000001 State change from LAUNCHED to RUNNING 2021-03-22 10:51:22,253 INFO rmapp.RMAppImpl (RMAppImpl.java:handle(715)) - application_1616340089879_4264 State change from ACCEPTED to RUNNING ``` 这说明啥呢，说明RMAppAttempt对象还没有变launched状态，AM的注册就来了。这会导致什么问题？ 问题就是[yarn-3260](https://issues.apache.org/jira/browse/YARN-3260)提到的，简要而言就是有如下图两个异步过程，一个过程(左边)是向缓存中添加token ,一个过程（右边）是从缓存中获取token。如果获取的过程比添加的过程要早执行，则会拿不到token。最麻烦的是获取的过程在获取返回之后，会执行编码（getEncoded）操作 ``` LOG.info("Setting client token master key"); response.setClientToAMTokenMasterKey(java.nio.ByteBuffer.wrap(rmContext .getClientToAMTokenSecretManager() .getMasterKey(applicationAttemptId).getEncoded())); ``` 如此就会出现NPE（NullPointerException） ![](/files/-MWO9Pd29Fi8eMAiXaLL) ## 3.解决办法 jira 提到的解决办法就是不要在allocated到launched过程去保存token ,而是把保存token 提前，放到ALLOCATED\_SAVING 到allocated 到过程去，这样保存token 之后，才去拉起的AM，然后才是AM注册。 ## 4.补充 这个问题本身比较简单，但是解决的门槛比较高，因为你得了解yarn 处理App的细节流程。最开始我们直接google ，并没有找到有用的信息（都指向yarn-site,yarn-core 的配置），直到后面我们通过在搜索前面加上 jira hadoop 关键字才看到有用信息。所以在直接google 没有什么用的时候，一定要去jira 上面看看 ``` jira hadoop org.apache.hadoop.mapreduce.v2.app.rm.RMCommunicator: Exception while registering java.lang.NullPointerException: java.lang.NullPointerException at org.apache.hadoop.yarn.server.resourcemanager.ApplicationMasterService.registerApplicationMaster(ApplicationMasterService.java:296) ``` 为什么会慢呢？无非是两个原因：1.中央异步处理器缓存队列处理比较慢，或者队列事件比较多。二. AMLaunchedTransition 处理过程慢。具体原因还要具体分析