[ https://issues.apache.org/jira/browse/YARN-7102?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16217597#comment-16217597 ]
Jason Lowe commented on YARN-7102: ---------------------------------- I'm wondering about the branch-2 patch test failures. The SLS failures are either bind exceptions or cast exceptions for fair scheduler metrics which I believe are unrelated. However twice now Jenkins has complained about TestResourceTrackerService which is very much a related test to the code being changed. If I run this shell script I can eventually get it to fail as well: {noformat} $ cd hadoop-yarn-project/hadoop-yarn/hadoop-yarn-server/hadoop-yarn-server-resourcemanager $ while :;do mvn surefire:test -Dtest=TestResourceTrackerService#testReconnectNode || break;done {noformat} It looks like the TestResourceTrackerService#testReconnectNode failure is related to this test output: {noformat} 2017-10-21 09:04:23,368 INFO [main] resourcemanager.ResourceTrackerService (ResourceTrackerService.java:registerNodeManager(403)) - Reconnect from the node at: host1 2017-10-21 09:04:23,368 INFO [main] resourcemanager.ResourceTrackerService (ResourceTrackerService.java:registerNodeManager(458)) - NodeManager from node host1(cmPort: 1234 httpPort: 3) registered with capability: <memory:5120, vCores:5>, assigned nodeId host1:1234 2017-10-21 09:04:23,368 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(192)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeReconnectEvent.EventType: RECONNECTED 2017-10-21 09:04:23,368 DEBUG [AsyncDispatcher event handler] rmnode.RMNodeImpl (RMNodeImpl.java:handle(659)) - Processing host1:1234 of type RECONNECTED 2017-10-21 09:04:23,368 INFO [main] resourcemanager.ResourceTrackerService (ResourceTrackerService.java:nodeHeartbeat(522)) - Too far behind rm response id:0 nm response id:1 2017-10-21 09:04:23,368 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(192)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeStatusEvent.EventType: STATUS_UPDATE 2017-10-21 09:04:23,368 DEBUG [AsyncDispatcher event handler] rmnode.RMNodeImpl (RMNodeImpl.java:handle(659)) - Processing host1:1234 of type STATUS_UPDATE 2017-10-21 09:04:23,368 ERROR [AsyncDispatcher event handler] rmnode.RMNodeImpl (RMNodeImpl.java:handle(666)) - Can't handle this event at current state org.apache.hadoop.yarn.state.InvalidStateTransitionException: Invalid event: STATUS_UPDATE at NEW at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:305) at org.apache.hadoop.yarn.state.StateMachineFactory.access$500(StateMachineFactory.java:46) at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:487) at org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeImpl.handle(RMNodeImpl.java:664) at org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeImpl.handle(RMNodeImpl.java:98) at org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$NodeEventDispatcher.handle(ResourceManager.java:1010) at org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$NodeEventDispatcher.handle(ResourceManager.java:994) at org.apache.hadoop.yarn.event.AsyncDispatcher.dispatch(AsyncDispatcher.java:201) at org.apache.hadoop.yarn.event.DrainDispatcher$1.run(DrainDispatcher.java:83) at java.lang.Thread.run(Thread.java:748) 2017-10-21 09:04:23,369 ERROR [AsyncDispatcher event handler] rmnode.RMNodeImpl (RMNodeImpl.java:handle(667)) - Invalid event STATUS_UPDATE on Node host1:1234 oldState NEW {noformat} I believe the test issue is related to the code change. I think something along these lines is occurring, but I haven't had time to delve into it further. # NM re-registers with a health status change and gets a response, so NM thinks next response is 0. In the meantime, RM has asynchronously sent a reconnect event to the RM. # NM heartbeats with 0 and that matches the RMNodeImpl, so RM responds with next response ID = 1 # RMNodeImpl finally gets the reconnected node event, and because it's a status change it swaps out the old node for the new RMNodeImpl, resetting the last response ID to 0. # NM heartbeats again with response ID 1. 1 != 0 so the RM thinks the NM is "too old," when in fact it is _ahead_ of the RM. This causes the RM to send a REBOOT command and remove the RMNodeImpl. # Test code blindly looks up the RMNodeImpl by hostname and finds nothing, since the RMNodeImpl reboot logic removed it, hence the NPE on line 1286 of the test. It looks like the response ID may be mishandled during the reconnect logic in cases where we swap out one node for another and the NM heartbeat races ahead of the reconnect processing. Before this code change the heartbeat wouldn't be rejected because it's ahead of the RMNodeImpl, but now with this change those heartbeats are rejected just as if the NM was behind the RM. > NM heartbeat stuck when responseId overflows MAX_INT > ---------------------------------------------------- > > Key: YARN-7102 > URL: https://issues.apache.org/jira/browse/YARN-7102 > Project: Hadoop YARN > Issue Type: Bug > Reporter: Botong Huang > Assignee: Botong Huang > Priority: Critical > Attachments: YARN-7102-branch-2.8.v10.patch, > YARN-7102-branch-2.8.v11.patch, YARN-7102-branch-2.8.v9.patch, > YARN-7102-branch-2.v9.patch, YARN-7102-branch-2.v9.patch, > YARN-7102-branch-2.v9.patch, YARN-7102.v1.patch, YARN-7102.v2.patch, > YARN-7102.v3.patch, YARN-7102.v4.patch, YARN-7102.v5.patch, > YARN-7102.v6.patch, YARN-7102.v7.patch, YARN-7102.v8.patch, YARN-7102.v9.patch > > > ResponseId overflow problem in NM-RM heartbeat. This is same as AM-RM > heartbeat in YARN-6640, please refer to YARN-6640 for details. -- This message was sent by Atlassian JIRA (v6.4.14#64029) --------------------------------------------------------------------- To unsubscribe, e-mail: yarn-issues-unsubscr...@hadoop.apache.org For additional commands, e-mail: yarn-issues-h...@hadoop.apache.org