You are viewing a plain text version of this content. The canonical link for it is here.
Posted to yarn-issues@hadoop.apache.org by "zhihai xu (JIRA)" <ji...@apache.org> on 2015/06/23 10:57:02 UTC
[jira] [Commented] (YARN-2871)
TestRMRestart#testRMRestartGetApplicationList sometime fails in trunk
[ https://issues.apache.org/jira/browse/YARN-2871?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14597368#comment-14597368 ]
zhihai xu commented on YARN-2871:
---------------------------------
I can work on this issue, Based on the failure logs https://builds.apache.org/job/PreCommit-YARN-Build/8323/testReport/org.apache.hadoop.yarn.server.resourcemanager/TestRMRestart/testRMRestartGetApplicationList_1_/, the root cause of this issue is a race condition in the test. {{logApplicationSummary}} is called when RMAppManager handles APP_COMPLETED RMAppManagerEvent. RMAppImpl sends APP_COMPLETED event to AsyncDispatcher thread. If AsyncDispatcher thread doesn't process APP_COMPLETED event on time, then the test will fail. I think If we add some delay before the verification, it will fix this issue.
The important logs from failed test:
{code}
2015-06-23 06:06:20,484 INFO [Thread-693] resourcemanager.ResourceManager (ResourceManager.java:serviceStart(572)) - Recovery started
2015-06-23 06:06:20,484 INFO [Thread-693] security.RMDelegationTokenSecretManager (RMDelegationTokenSecretManager.java:recover(178)) - recovering RMDelegationTokenSecretManager.
2015-06-23 06:06:20,484 INFO [Thread-693] resourcemanager.RMAppManager (RMAppManager.java:recover(425)) - Recovering 3 applications
2015-06-23 06:06:20,485 DEBUG [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1435039562888_0001 of type RECOVER
2015-06-23 06:06:20,485 INFO [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:recover(781)) - Recovering app: application_1435039562888_0001 with 1 attempts and final state = FINISHED
2015-06-23 06:06:20,485 INFO [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:recover(827)) - Recovering attempt: appattempt_1435039562888_0001_000001 with final state: FINISHED
2015-06-23 06:06:20,485 DEBUG [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1435039562888_0001_000001 of type RECOVER
2015-06-23 06:06:20,486 INFO [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(793)) - appattempt_1435039562888_0001_000001 State change from NEW to FINISHED
2015-06-23 06:06:20,486 INFO [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:handle(768)) - application_1435039562888_0001 State change from NEW to FINISHED
2015-06-23 06:06:20,486 DEBUG [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1435039562888_0002 of type RECOVER
2015-06-23 06:06:20,486 INFO [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:recover(781)) - Recovering app: application_1435039562888_0002 with 1 attempts and final state = FAILED
2015-06-23 06:06:20,487 INFO [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:recover(827)) - Recovering attempt: appattempt_1435039562888_0002_000001 with final state: FAILED
2015-06-23 06:06:20,487 DEBUG [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1435039562888_0002_000001 of type RECOVER
2015-06-23 06:06:20,487 INFO [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(793)) - appattempt_1435039562888_0002_000001 State change from NEW to FAILED
2015-06-23 06:06:20,487 INFO [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:handle(768)) - application_1435039562888_0002 State change from NEW to FAILED
2015-06-23 06:06:20,488 DEBUG [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1435039562888_0003 of type RECOVER
2015-06-23 06:06:20,488 INFO [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:recover(781)) - Recovering app: application_1435039562888_0003 with 1 attempts and final state = KILLED
2015-06-23 06:06:20,488 INFO [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:recover(827)) - Recovering attempt: appattempt_1435039562888_0003_000001 with final state: KILLED
2015-06-23 06:06:20,489 DEBUG [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1435039562888_0003_000001 of type RECOVER
2015-06-23 06:06:20,489 INFO [Thread-693] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(793)) - appattempt_1435039562888_0003_000001 State change from NEW to KILLED
2015-06-23 06:06:20,489 INFO [Thread-693] rmapp.RMAppImpl (RMAppImpl.java:handle(768)) - application_1435039562888_0003 State change from NEW to KILLED
2015-06-23 06:06:20,489 INFO [Thread-693] resourcemanager.ResourceManager (ResourceManager.java:serviceStart(579)) - Recovery ended
2015-06-23 06:06:20,489 DEBUG [Thread-693] service.CompositeService (CompositeService.java:serviceStart(115)) - RMActiveServices: starting services, size=15
2015-06-23 06:06:20,489 INFO [Thread-693] security.RMContainerTokenSecretManager (RMContainerTokenSecretManager.java:rollMasterKey(105)) - Rolling master-key for container-tokens
2015-06-23 06:06:20,489 INFO [Thread-693] security.RMContainerTokenSecretManager (RMContainerTokenSecretManager.java:rollMasterKey(110)) - Going to activate master-key with key-id -644495556 in 900000ms
2015-06-23 06:06:20,489 INFO [Thread-693] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:rollMasterKey(95)) - Rolling master-key for nm-tokens
2015-06-23 06:06:20,489 INFO [Thread-693] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:rollMasterKey(100)) - Going to activate master-key with key-id 1471860283 in 900000ms
2015-06-23 06:06:20,490 INFO [Thread-693] delegation.AbstractDelegationTokenSecretManager (AbstractDelegationTokenSecretManager.java:updateCurrentKey(336)) - Updating the current master key for generating delegation tokens
2015-06-23 06:06:20,490 INFO [Thread-693] security.RMDelegationTokenSecretManager (RMDelegationTokenSecretManager.java:storeNewMasterKey(87)) - storing master key with keyID 3
2015-06-23 06:06:20,490 DEBUG [Thread-693] recovery.RMStateStore (RMStateStore.java:handleStoreEvent(832)) - Processing event of type STORE_MASTERKEY
2015-06-23 06:06:20,490 INFO [Thread-693] recovery.RMStateStore (RMStateStore.java:transition(365)) - Storing RMDTMasterKey.
2015-06-23 06:06:20,490 INFO [Thread-693] recovery.RMStateStore (MemoryRMStateStore.java:storeRMDTMasterKeyState(213)) - Store RMDT master key with key id: 3. Currently rmDTMasterKeyState size: 3
2015-06-23 06:06:20,490 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.RMSecretManagerService is started
2015-06-23 06:06:20,490 INFO [Thread[Thread-717,5,main]] delegation.AbstractDelegationTokenSecretManager (AbstractDelegationTokenSecretManager.java:run(649)) - Starting expired delegation token remover thread, tokenRemoverScanInterval=60 min(s)
2015-06-23 06:06:20,491 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.ContainerAllocationExpirer is started
2015-06-23 06:06:20,491 INFO [Thread[Thread-717,5,main]] delegation.AbstractDelegationTokenSecretManager (AbstractDelegationTokenSecretManager.java:updateCurrentKey(336)) - Updating the current master key for generating delegation tokens
2015-06-23 06:06:20,492 INFO [Thread[Thread-717,5,main]] security.RMDelegationTokenSecretManager (RMDelegationTokenSecretManager.java:storeNewMasterKey(87)) - storing master key with keyID 4
2015-06-23 06:06:20,492 DEBUG [Thread[Thread-717,5,main]] recovery.RMStateStore (RMStateStore.java:handleStoreEvent(832)) - Processing event of type STORE_MASTERKEY
2015-06-23 06:06:20,492 INFO [Thread[Thread-717,5,main]] recovery.RMStateStore (RMStateStore.java:transition(365)) - Storing RMDTMasterKey.
2015-06-23 06:06:20,492 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service AMLivelinessMonitor is started
2015-06-23 06:06:20,492 INFO [Thread[Thread-717,5,main]] recovery.RMStateStore (MemoryRMStateStore.java:storeRMDTMasterKeyState(213)) - Store RMDT master key with key id: 4. Currently rmDTMasterKeyState size: 4
2015-06-23 06:06:20,493 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service AMLivelinessMonitor is started
2015-06-23 06:06:20,493 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.nodelabels.CommonNodeLabelsManager is started
2015-06-23 06:06:20,493 DEBUG [Thread-693] service.CompositeService (CompositeService.java:serviceStart(115)) - org.apache.hadoop.yarn.server.resourcemanager.ahs.RMApplicationHistoryWriter: starting services, size=0
2015-06-23 06:06:20,493 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ahs.RMApplicationHistoryWriter is started
2015-06-23 06:06:20,493 DEBUG [Thread-693] service.CompositeService (CompositeService.java:serviceStart(115)) - org.apache.hadoop.yarn.server.resourcemanager.metrics.SystemMetricsPublisher: starting services, size=0
2015-06-23 06:06:20,493 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.metrics.SystemMetricsPublisher is started
2015-06-23 06:06:20,493 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.NodesListManager is started
2015-06-23 06:06:20,494 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.AllocationFileLoaderService is started
2015-06-23 06:06:20,494 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler is started
2015-06-23 06:06:20,494 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$SchedulerEventDispatcher is started
2015-06-23 06:06:20,494 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service NMLivelinessMonitor is started
2015-06-23 06:06:20,495 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ResourceTrackerService is started
2015-06-23 06:06:20,495 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ApplicationMasterService is started
2015-06-23 06:06:20,495 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ClientRMService is started
2015-06-23 06:06:20,495 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.amlauncher.ApplicationMasterLauncher is started
2015-06-23 06:06:20,495 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service RMActiveServices is started
2015-06-23 06:06:20,495 INFO [Thread-693] resourcemanager.ResourceManager (ResourceManager.java:transitionToActive(1049)) - Transitioned to active state
2015-06-23 06:06:20,495 DEBUG [Thread-693] service.CompositeService (CompositeService.java:serviceStart(115)) - ResourceManager: starting services, size=2
2015-06-23 06:06:20,496 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service Dispatcher is started
2015-06-23 06:06:20,496 DEBUG [Thread-693] service.CompositeService (CompositeService.java:serviceStart(115)) - org.apache.hadoop.yarn.server.resourcemanager.AdminService: starting services, size=0
2015-06-23 06:06:20,496 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.AdminService is started
2015-06-23 06:06:20,496 DEBUG [Thread-693] service.AbstractService (AbstractService.java:start(197)) - Service ResourceManager is started
2015-06-23 06:06:20,496 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.RMAppManagerEvent.EventType: APP_COMPLETED
2015-06-23 06:06:20,496 DEBUG [Thread-693] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for jenkins (auth:KERBEROS) on application application_1435039562888_0003 owned by user
2015-06-23 06:06:20,497 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0003_000001
2015-06-23 06:06:20,497 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0003_000001
2015-06-23 06:06:20,497 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0003_000001
2015-06-23 06:06:20,497 DEBUG [Thread-693] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for jenkins (auth:KERBEROS) on application application_1435039562888_0002 owned by user
2015-06-23 06:06:20,497 DEBUG [AsyncDispatcher event handler] resourcemanager.RMAppManager (RMAppManager.java:handle(434)) - RMAppManager processing event for application_1435039562888_0001 of type APP_COMPLETED
2015-06-23 06:06:20,498 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0002_000001
2015-06-23 06:06:20,498 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0002_000001
2015-06-23 06:06:20,498 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0002_000001
2015-06-23 06:06:20,498 INFO [AsyncDispatcher event handler] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(148)) - USER=user OPERATION=Application Finished - Succeeded TARGET=RMAppManager RESULT=SUCCESS APPID=application_1435039562888_0001
2015-06-23 06:06:20,498 DEBUG [Thread-693] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for jenkins (auth:KERBEROS) on application application_1435039562888_0001 owned by user
2015-06-23 06:06:20,498 DEBUG [AsyncDispatcher event handler] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0001_000001
2015-06-23 06:06:20,499 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0001_000001
2015-06-23 06:06:20,499 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0001_000001
2015-06-23 06:06:20,499 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0001_000001
2015-06-23 06:06:20,499 INFO [AsyncDispatcher event handler] resourcemanager.RMAppManager$ApplicationSummary (RMAppManager.java:logAppSummary(187)) - appId=application_1435039562888_0001,name=name,user=user,queue=default,state=FINISHED,trackingUrl=http://asf906.gq1.ygridcore.net:8088/proxy/application_1435039562888_0001/,appMasterHost=N/A,startTime=1435039562899,finishTime=1435039567908,finalStatus=SUCCEEDED,memorySeconds=3586,vcoreSeconds=3,preemptedAMContainers=0,preemptedNonAMContainers=0,preemptedResources=<memory:0\, vCores:0>,applicationType=myType
2015-06-23 06:06:20,499 DEBUG [Thread-693] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for jenkins (auth:KERBEROS) on application application_1435039562888_0003 owned by user
2015-06-23 06:06:20,499 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.RMAppManagerEvent.EventType: APP_COMPLETED
2015-06-23 06:06:20,500 DEBUG [AsyncDispatcher event handler] resourcemanager.RMAppManager (RMAppManager.java:handle(434)) - RMAppManager processing event for application_1435039562888_0002 of type APP_COMPLETED
2015-06-23 06:06:20,500 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0003_000001
2015-06-23 06:06:20,500 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0003_000001
2015-06-23 06:06:20,500 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0003_000001
2015-06-23 06:06:20,500 DEBUG [Thread-693] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for jenkins (auth:KERBEROS) on application application_1435039562888_0002 owned by user
2015-06-23 06:06:20,500 WARN [AsyncDispatcher event handler] resourcemanager.RMAuditLogger (RMAuditLogger.java:logFailure(263)) - USER=user OPERATION=Application Finished - Failed TARGET=RMAppManager RESULT=FAILURE DESCRIPTION=App failed with state: FAILED PERMISSIONS=Application application_1435039562888_0002 failed 1 times due to AM Container for appattempt_1435039562888_0002_000001 exited with exitCode: 0
Failing this attempt.Diagnostics: SuccessFor more detailed output, check the application tracking page: http://asf906.gq1.ygridcore.net:8088/cluster/app/application_1435039562888_0002 Then click on links to logs of each attempt.
. Failing the application. APPID=application_1435039562888_0002
2015-06-23 06:06:20,501 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0002_000001
2015-06-23 06:06:20,501 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0002_000001
2015-06-23 06:06:20,501 DEBUG [AsyncDispatcher event handler] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0002_000001
2015-06-23 06:06:20,501 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0002_000001
2015-06-23 06:06:20,501 DEBUG [Thread-693] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for jenkins (auth:KERBEROS) on application application_1435039562888_0001 owned by user
2015-06-23 06:06:20,501 INFO [AsyncDispatcher event handler] resourcemanager.RMAppManager$ApplicationSummary (RMAppManager.java:logAppSummary(187)) - appId=application_1435039562888_0002,name=name,user=user,queue=default,state=FAILED,trackingUrl=http://asf906.gq1.ygridcore.net:8088/proxy/application_1435039562888_0002/,appMasterHost=N/A,startTime=1435039569909,finishTime=1435039573919,finalStatus=FAILED,memorySeconds=2564,vcoreSeconds=2,preemptedAMContainers=0,preemptedNonAMContainers=0,preemptedResources=<memory:0\, vCores:0>,applicationType=myType
2015-06-23 06:06:20,502 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0001_000001
2015-06-23 06:06:20,502 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0001_000001
2015-06-23 06:06:20,502 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.RMAppManagerEvent.EventType: APP_COMPLETED
2015-06-23 06:06:20,502 DEBUG [Thread-693] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0001_000001
2015-06-23 06:06:20,502 DEBUG [AsyncDispatcher event handler] resourcemanager.RMAppManager (RMAppManager.java:handle(434)) - RMAppManager processing event for application_1435039562888_0003 of type APP_COMPLETED
2015-06-23 06:06:20,502 INFO [AsyncDispatcher event handler] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(148)) - USER=user OPERATION=Application Finished - Killed TARGET=RMAppManager RESULT=SUCCESS APPID=application_1435039562888_0003
2015-06-23 06:06:20,503 DEBUG [AsyncDispatcher event handler] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435039562888_0003_000001
2015-06-23 06:06:20,503 INFO [AsyncDispatcher event handler] resourcemanager.RMAppManager$ApplicationSummary (RMAppManager.java:logAppSummary(187)) - appId=application_1435039562888_0003,name=name,user=user,queue=default,state=KILLED,trackingUrl=http://asf906.gq1.ygridcore.net:8088/proxy/application_1435039562888_0003/,appMasterHost=N/A,startTime=1435039574916,finishTime=1435039578925,finalStatus=KILLED,memorySeconds=6,vcoreSeconds=0,preemptedAMContainers=0,preemptedNonAMContainers=0,preemptedResources=<memory:0\, vCores:0>,applicationType=myType
2015-06-23 06:06:20,508 DEBUG [main] service.AbstractService (AbstractService.java:enterState(452)) - Service: ResourceManager entered state STOPPED
{code}
>From above logs, you can see RMAppManager processing event for application_1435039562888_0003 of type APP_COMPLETED is after all Verifying access-type VIEW_APP which is called from {{rm2.getClientRMService().getApplications}}.
The corresponding logs from succeeded test:
{code}
2015-06-22 23:45:01,319 INFO [Thread-1] resourcemanager.ResourceManager (ResourceManager.java:serviceStart(572)) - Recovery started
2015-06-22 23:45:01,320 INFO [Thread-1] security.RMDelegationTokenSecretManager (RMDelegationTokenSecretManager.java:recover(178)) - recovering RMDelegationTokenSecretManager.
2015-06-22 23:45:01,348 INFO [Thread-1] resourcemanager.RMAppManager (RMAppManager.java:recover(425)) - Recovering 3 applications
2015-06-22 23:45:01,349 DEBUG [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1435041883856_0001 of type RECOVER
2015-06-22 23:45:01,349 INFO [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:recover(781)) - Recovering app: application_1435041883856_0001 with 1 attempts and final state = FINISHED
2015-06-22 23:45:01,350 INFO [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:recover(827)) - Recovering attempt: appattempt_1435041883856_0001_000001 with final state: FINISHED
2015-06-22 23:45:01,351 DEBUG [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1435041883856_0001_000001 of type RECOVER
2015-06-22 23:45:01,351 INFO [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(793)) - appattempt_1435041883856_0001_000001 State change from NEW to FINISHED
2015-06-22 23:45:01,351 INFO [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:handle(768)) - application_1435041883856_0001 State change from NEW to FINISHED
2015-06-22 23:45:01,352 DEBUG [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1435041883856_0002 of type RECOVER
2015-06-22 23:45:01,352 INFO [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:recover(781)) - Recovering app: application_1435041883856_0002 with 1 attempts and final state = FAILED
2015-06-22 23:45:01,353 INFO [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:recover(827)) - Recovering attempt: appattempt_1435041883856_0002_000001 with final state: FAILED
2015-06-22 23:45:01,353 DEBUG [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1435041883856_0002_000001 of type RECOVER
2015-06-22 23:45:01,354 INFO [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(793)) - appattempt_1435041883856_0002_000001 State change from NEW to FAILED
2015-06-22 23:45:01,354 INFO [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:handle(768)) - application_1435041883856_0002 State change from NEW to FAILED
2015-06-22 23:45:01,354 DEBUG [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1435041883856_0003 of type RECOVER
2015-06-22 23:45:01,354 INFO [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:recover(781)) - Recovering app: application_1435041883856_0003 with 1 attempts and final state = KILLED
2015-06-22 23:45:01,355 INFO [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:recover(827)) - Recovering attempt: appattempt_1435041883856_0003_000001 with final state: KILLED
2015-06-22 23:45:01,356 DEBUG [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1435041883856_0003_000001 of type RECOVER
2015-06-22 23:45:01,356 INFO [Thread-1] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(793)) - appattempt_1435041883856_0003_000001 State change from NEW to KILLED
2015-06-22 23:45:01,356 INFO [Thread-1] rmapp.RMAppImpl (RMAppImpl.java:handle(768)) - application_1435041883856_0003 State change from NEW to KILLED
2015-06-22 23:45:01,356 INFO [Thread-1] resourcemanager.ResourceManager (ResourceManager.java:serviceStart(579)) - Recovery ended
2015-06-22 23:45:01,356 DEBUG [Thread-1] service.CompositeService (CompositeService.java:serviceStart(115)) - RMActiveServices: starting services, size=15
2015-06-22 23:45:01,356 INFO [Thread-1] security.RMContainerTokenSecretManager (RMContainerTokenSecretManager.java:rollMasterKey(105)) - Rolling master-key for container-tokens
2015-06-22 23:45:01,356 INFO [Thread-1] security.RMContainerTokenSecretManager (RMContainerTokenSecretManager.java:rollMasterKey(110)) - Going to activate master-key with key-id 344850257 in 900000ms
2015-06-22 23:45:01,357 INFO [Thread-1] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:rollMasterKey(95)) - Rolling master-key for nm-tokens
2015-06-22 23:45:01,357 INFO [Thread-1] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:rollMasterKey(100)) - Going to activate master-key with key-id -867844649 in 900000ms
2015-06-22 23:45:01,357 INFO [Thread-1] delegation.AbstractDelegationTokenSecretManager (AbstractDelegationTokenSecretManager.java:updateCurrentKey(336)) - Updating the current master key for generating delegation tokens
2015-06-22 23:45:01,357 INFO [Thread-1] security.RMDelegationTokenSecretManager (RMDelegationTokenSecretManager.java:storeNewMasterKey(87)) - storing master key with keyID 3
2015-06-22 23:45:01,357 DEBUG [Thread-1] recovery.RMStateStore (RMStateStore.java:handleStoreEvent(832)) - Processing event of type STORE_MASTERKEY
2015-06-22 23:45:01,357 INFO [Thread-1] recovery.RMStateStore (RMStateStore.java:transition(365)) - Storing RMDTMasterKey.
2015-06-22 23:45:01,357 INFO [Thread-1] recovery.RMStateStore (MemoryRMStateStore.java:storeRMDTMasterKeyState(213)) - Store RMDT master key with key id: 3. Currently rmDTMasterKeyState size: 3
2015-06-22 23:45:01,358 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.RMSecretManagerService is started
2015-06-22 23:45:01,358 INFO [Thread[Thread-21,5,main]] delegation.AbstractDelegationTokenSecretManager (AbstractDelegationTokenSecretManager.java:run(649)) - Starting expired delegation token remover thread, tokenRemoverScanInterval=60 min(s)
2015-06-22 23:45:01,358 INFO [Thread[Thread-21,5,main]] delegation.AbstractDelegationTokenSecretManager (AbstractDelegationTokenSecretManager.java:updateCurrentKey(336)) - Updating the current master key for generating delegation tokens
2015-06-22 23:45:01,358 INFO [Thread[Thread-21,5,main]] security.RMDelegationTokenSecretManager (RMDelegationTokenSecretManager.java:storeNewMasterKey(87)) - storing master key with keyID 4
2015-06-22 23:45:01,358 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.ContainerAllocationExpirer is started
2015-06-22 23:45:01,359 DEBUG [Thread[Thread-21,5,main]] recovery.RMStateStore (RMStateStore.java:handleStoreEvent(832)) - Processing event of type STORE_MASTERKEY
2015-06-22 23:45:01,359 INFO [Thread[Thread-21,5,main]] recovery.RMStateStore (RMStateStore.java:transition(365)) - Storing RMDTMasterKey.
2015-06-22 23:45:01,359 INFO [Thread[Thread-21,5,main]] recovery.RMStateStore (MemoryRMStateStore.java:storeRMDTMasterKeyState(213)) - Store RMDT master key with key id: 4. Currently rmDTMasterKeyState size: 4
2015-06-22 23:45:01,359 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service AMLivelinessMonitor is started
2015-06-22 23:45:01,359 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service AMLivelinessMonitor is started
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.nodelabels.CommonNodeLabelsManager is started
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.CompositeService (CompositeService.java:serviceStart(115)) - org.apache.hadoop.yarn.server.resourcemanager.ahs.RMApplicationHistoryWriter: starting services, size=0
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ahs.RMApplicationHistoryWriter is started
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.CompositeService (CompositeService.java:serviceStart(115)) - org.apache.hadoop.yarn.server.resourcemanager.metrics.SystemMetricsPublisher: starting services, size=0
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.metrics.SystemMetricsPublisher is started
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.NodesListManager is started
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CapacityScheduler is started
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$SchedulerEventDispatcher is started
2015-06-22 23:45:01,360 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service NMLivelinessMonitor is started
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ResourceTrackerService is started
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ApplicationMasterService is started
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.ClientRMService is started
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.amlauncher.ApplicationMasterLauncher is started
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service RMActiveServices is started
2015-06-22 23:45:01,361 INFO [Thread-1] resourcemanager.ResourceManager (ResourceManager.java:transitionToActive(1049)) - Transitioned to active state
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.CompositeService (CompositeService.java:serviceStart(115)) - ResourceManager: starting services, size=2
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service Dispatcher is started
2015-06-22 23:45:01,361 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.RMAppManagerEvent.EventType: APP_COMPLETED
2015-06-22 23:45:01,361 DEBUG [Thread-1] service.CompositeService (CompositeService.java:serviceStart(115)) - org.apache.hadoop.yarn.server.resourcemanager.AdminService: starting services, size=0
2015-06-22 23:45:01,362 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service org.apache.hadoop.yarn.server.resourcemanager.AdminService is started
2015-06-22 23:45:01,362 DEBUG [Thread-1] service.AbstractService (AbstractService.java:start(197)) - Service ResourceManager is started
2015-06-22 23:45:01,363 DEBUG [AsyncDispatcher event handler] resourcemanager.RMAppManager (RMAppManager.java:handle(434)) - RMAppManager processing event for application_1435041883856_0001 of type APP_COMPLETED
2015-06-22 23:45:01,363 INFO [AsyncDispatcher event handler] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(148)) - USER=user OPERATION=Application Finished - Succeeded TARGET=RMAppManager RESULT=SUCCESS APPID=application_1435041883856_0001
2015-06-22 23:45:01,363 DEBUG [AsyncDispatcher event handler] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0001_000001
2015-06-22 23:45:01,364 INFO [AsyncDispatcher event handler] resourcemanager.RMAppManager$ApplicationSummary (RMAppManager.java:logAppSummary(187)) - appId=application_1435041883856_0001,name=name,user=user,queue=default,state=FINISHED,trackingUrl=http://zxu-mbp.local:8088/proxy/application_1435041883856_0001/,appMasterHost=N/A,startTime=1435041884030,finishTime=1435041888611,finalStatus=SUCCEEDED,memorySeconds=112,vcoreSeconds=0,preemptedAMContainers=0,preemptedNonAMContainers=0,preemptedResources=<memory:0\, vCores:0>,applicationType=myType
2015-06-22 23:45:01,365 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.RMAppManagerEvent.EventType: APP_COMPLETED
2015-06-22 23:45:01,365 DEBUG [AsyncDispatcher event handler] resourcemanager.RMAppManager (RMAppManager.java:handle(434)) - RMAppManager processing event for application_1435041883856_0002 of type APP_COMPLETED
2015-06-22 23:45:01,365 WARN [AsyncDispatcher event handler] resourcemanager.RMAuditLogger (RMAuditLogger.java:logFailure(263)) - USER=user OPERATION=Application Finished - Failed TARGET=RMAppManager RESULT=FAILURE DESCRIPTION=App failed with state: FAILED PERMISSIONS=Application application_1435041883856_0002 failed 1 times due to AM Container for appattempt_1435041883856_0002_000001 exited with exitCode: 0
Failing this attempt.Diagnostics: SuccessFor more detailed output, check the application tracking page: http://zxu-mbp.local:8088/cluster/app/application_1435041883856_0002 Then click on links to logs of each attempt.
. Failing the application. APPID=application_1435041883856_0002
2015-06-22 23:45:01,366 DEBUG [AsyncDispatcher event handler] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0002_000001
2015-06-22 23:45:01,366 INFO [AsyncDispatcher event handler] resourcemanager.RMAppManager$ApplicationSummary (RMAppManager.java:logAppSummary(187)) - appId=application_1435041883856_0002,name=name,user=user,queue=default,state=FAILED,trackingUrl=http://zxu-mbp.local:8088/proxy/application_1435041883856_0002/,appMasterHost=N/A,startTime=1435041890627,finishTime=1435041894642,finalStatus=FAILED,memorySeconds=2565,vcoreSeconds=2,preemptedAMContainers=0,preemptedNonAMContainers=0,preemptedResources=<memory:0\, vCores:0>,applicationType=myType
2015-06-22 23:45:01,366 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.RMAppManagerEvent.EventType: APP_COMPLETED
2015-06-22 23:45:01,366 DEBUG [AsyncDispatcher event handler] resourcemanager.RMAppManager (RMAppManager.java:handle(434)) - RMAppManager processing event for application_1435041883856_0003 of type APP_COMPLETED
2015-06-22 23:45:01,367 INFO [AsyncDispatcher event handler] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(148)) - USER=user OPERATION=Application Finished - Killed TARGET=RMAppManager RESULT=SUCCESS APPID=application_1435041883856_0003
2015-06-22 23:45:01,367 DEBUG [AsyncDispatcher event handler] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0003_000001
2015-06-22 23:45:01,368 INFO [AsyncDispatcher event handler] resourcemanager.RMAppManager$ApplicationSummary (RMAppManager.java:logAppSummary(187)) - appId=application_1435041883856_0003,name=name,user=user,queue=default,state=KILLED,trackingUrl=http://zxu-mbp.local:8088/proxy/application_1435041883856_0003/,appMasterHost=N/A,startTime=1435041895640,finishTime=1435041899657,finalStatus=KILLED,memorySeconds=18,vcoreSeconds=0,preemptedAMContainers=0,preemptedNonAMContainers=0,preemptedResources=<memory:0\, vCores:0>,applicationType=myType
2015-06-22 23:45:01,368 DEBUG [Thread-1] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for zxu (auth:SIMPLE) on application application_1435041883856_0001 owned by user
2015-06-22 23:45:01,370 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0001_000001
2015-06-22 23:45:01,370 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0001_000001
2015-06-22 23:45:01,370 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0001_000001
2015-06-22 23:45:01,376 DEBUG [Thread-1] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for zxu (auth:SIMPLE) on application application_1435041883856_0002 owned by user
2015-06-22 23:45:01,377 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0002_000001
2015-06-22 23:45:01,377 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0002_000001
2015-06-22 23:45:01,377 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0002_000001
2015-06-22 23:45:01,378 DEBUG [Thread-1] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for zxu (auth:SIMPLE) on application application_1435041883856_0003 owned by user
2015-06-22 23:45:01,378 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0003_000001
2015-06-22 23:45:01,379 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0003_000001
2015-06-22 23:45:01,379 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0003_000001
2015-06-22 23:45:01,382 DEBUG [Thread-1] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for zxu (auth:SIMPLE) on application application_1435041883856_0001 owned by user
2015-06-22 23:45:01,384 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0001_000001
2015-06-22 23:45:01,384 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0001_000001
2015-06-22 23:45:01,384 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0001_000001
2015-06-22 23:45:01,384 DEBUG [Thread-1] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for zxu (auth:SIMPLE) on application application_1435041883856_0002 owned by user
2015-06-22 23:45:01,386 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0002_000001
2015-06-22 23:45:01,386 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0002_000001
2015-06-22 23:45:01,386 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0002_000001
2015-06-22 23:45:01,386 DEBUG [Thread-1] security.ApplicationACLsManager (ApplicationACLsManager.java:checkAccess(102)) - Verifying access-type VIEW_APP for zxu (auth:SIMPLE) on application application_1435041883856_0003 owned by user
2015-06-22 23:45:01,387 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0003_000001
2015-06-22 23:45:01,387 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0003_000001
2015-06-22 23:45:01,387 DEBUG [Thread-1] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getAppResourceUsageReport(255)) - Request for appInfo of unknown attempt appattempt_1435041883856_0003_000001
2015-06-22 23:45:01,395 DEBUG [main] service.AbstractService (AbstractService.java:enterState(452)) - Service: ResourceManager entered state STOPPED
{code}
>From above logs, you can see RMAppManager processing event for application_1435041883856_0003 of type APP_COMPLETED is before Verifying access-type VIEW_APP.
> TestRMRestart#testRMRestartGetApplicationList sometime fails in trunk
> ---------------------------------------------------------------------
>
> Key: YARN-2871
> URL: https://issues.apache.org/jira/browse/YARN-2871
> Project: Hadoop YARN
> Issue Type: Test
> Reporter: Ted Yu
> Assignee: zhihai xu
> Priority: Minor
>
> From trunk build #746 (https://builds.apache.org/job/Hadoop-Yarn-trunk/746):
> {code}
> Failed tests:
> TestRMRestart.testRMRestartGetApplicationList:957
> rMAppManager.logApplicationSummary(
> isA(org.apache.hadoop.yarn.api.records.ApplicationId)
> );
> Wanted 3 times:
> -> at org.apache.hadoop.yarn.server.resourcemanager.TestRMRestart.testRMRestartGetApplicationList(TestRMRestart.java:957)
> But was 2 times:
> -> at org.apache.hadoop.yarn.server.resourcemanager.RMAppManager.handle(RMAppManager.java:66)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)