[
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)
