Mailing-List: contact yarn-issues-help@hadoop.apache.org; run by ezmlm
Precedence: bulk
Date: Fri, 1 Dec 2017 11:00:00 +0000 (UTC)
From: "Tao Yang (JIRA)" <jira@apache.org>
To: yarn-issues@hadoop.apache.org
Message-ID: <JIRA.13122149.1512125790000.364125.1512126000321@Atlassian.JIRA>
In-Reply-To: <JIRA.13122149.1512125790000@Atlassian.JIRA>
References: <JIRA.13122149.1512125790000@Atlassian.JIRA> <JIRA.13122149.1512125790832@jira-lw-us.apache.org>
Subject: [jira] [Updated] (YARN-7593) SessionMovedException in
 ZKRMStateStore and can't recover
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
archived-at: Fri, 01 Dec 2017 11:00:07 -0000


     [ https://issues.apache.org/jira/browse/YARN-7593?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Tao Yang updated YARN-7593:
---------------------------
    Summary: SessionMovedException in ZKRMStateStore and can't recover  (was: SessionMovedException in ZKRMStateStore and can't auto recover after ZK connection timeout)

> SessionMovedException in ZKRMStateStore and can't recover
> ---------------------------------------------------------
>
>                 Key: YARN-7593
>                 URL: https://issues.apache.org/jira/browse/YARN-7593
>             Project: Hadoop YARN
>          Issue Type: Bug
>          Components: resourcemanager
>    Affects Versions: 2.9.0
>            Reporter: Tao Yang
>
> RM may throw SessionMovedException and can't recover ZKRMStateStore after zk connection timeout. 
> In our case, after connection with zk-server-5 timeout, zk client in ZKRMStateStore reconnected with zk-server-1 and timeout again, then reconnected to zk-server-4. After zk cluster backed to normal, zk client in ZKRMStateStore still can't recover and continued to throw SessionMovedException with fixed interval(about half a hour). The logs of zk servers show that it still try to connect with zk-server-5(outdated connection) but not zk-server-4(latest connection).
> Exception stack:
> {noformat}
> ERROR [AsyncDispatcher event handler] org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore: Error storing app: application_1498833634675_173952
> org.apache.zookeeper.KeeperException$SessionMovedException: KeeperErrorCode = Session moved
>         at org.apache.zookeeper.KeeperException.create(KeeperException.java:131)
>         at org.apache.zookeeper.ZooKeeper.multiInternal(ZooKeeper.java:949)
>         at org.apache.zookeeper.ZooKeeper.multi(ZooKeeper.java:915)
>         at org.apache.curator.framework.imps.CuratorTransactionImpl.doOperation(CuratorTransactionImpl.java:159)
>         at org.apache.curator.framework.imps.CuratorTransactionImpl.access$200(CuratorTransactionImpl.java:44)
>         at org.apache.curator.framework.imps.CuratorTransactionImpl$2.call(CuratorTransactionImpl.java:129)
>         at org.apache.curator.framework.imps.CuratorTransactionImpl$2.call(CuratorTransactionImpl.java:125)
>         at org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:107)
>         at org.apache.curator.framework.imps.CuratorTransactionImpl.commit(CuratorTransactionImpl.java:122)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.ZKRMStateStore$SafeTransaction.commit(ZKRMStateStore.java:943)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.ZKRMStateStore.safeCreate(ZKRMStateStore.java:903)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.ZKRMStateStore.storeApplicationStateInternal(ZKRMStateStore.java:563)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore$StoreAppTransition.transition(RMStateStore.java:213)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore$StoreAppTransition.transition(RMStateStore.java:195)
>         at org.apache.hadoop.yarn.state.StateMachineFactory$MultipleInternalArc.doTransition(StateMachineFactory.java:385)
>         at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:302)
>         at org.apache.hadoop.yarn.state.StateMachineFactory.access$300(StateMachineFactory.java:46)
>         at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:448)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore.handleStoreEvent(RMStateStore.java:1033)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore$ForwardingEventHandler.handle(RMStateStore.java:1114)
>         at org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore$ForwardingEventHandler.handle(RMStateStore.java:1109)
>         at org.apache.hadoop.yarn.event.AsyncDispatcher.dispatch(AsyncDispatcher.java:184)
>         at org.apache.hadoop.yarn.event.AsyncDispatcher$1.run(AsyncDispatcher.java:110)
>         at java.lang.Thread.run(Thread.java:834)
> {noformat}
> RM logs:
> {noformat}
> 2017-11-25 15:26:27,680 INFO [main-SendThread(zk-server-5:2181)] org.apache.zookeeper.ClientCnxn: Client session timed out, have not heard from server in 8004ms for sessionid 0x55cf8f81ebd7f1a, closing socket connection and attempting reconnect
> 2017-11-25 15:26:27,781 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager: State change: SUSPENDED
> 2017-11-25 15:26:27,968 INFO [main-SendThread(zk-server-1:2181)] org.apache.zookeeper.ClientCnxn: Opening socket connection to server zk-server-1:2181. Will not attempt to authenticate using SASL (unknown error)
> 2017-11-25 15:26:27,968 INFO [main-SendThread(zk-server-1:2181)] org.apache.zookeeper.ClientCnxn: Socket connection established to zk-server-1:2181, initiating session
> 2017-11-25 15:26:28,683 INFO [Socket Reader #1 for port 8030] SecurityLogger.org.apache.hadoop.ipc.Server: Auth successful for appattempt_1498833634675_173646_000001 (auth:SIMPLE)
> 2017-11-25 15:26:29,060 INFO [Socket Reader #1 for port 8030] SecurityLogger.org.apache.hadoop.ipc.Server: Auth successful for appattempt_1498833634675_173701_000001 (auth:SIMPLE)
> 2017-11-25 15:26:30,370 INFO [main-SendThread(zk-server-1:2181)] org.apache.zookeeper.ClientCnxn: Client session timed out, have not heard from server in 2402ms for sessionid 0x55cf8f81ebd7f1a, closing socket connection and attempting reconnect
> 2017-11-25 15:26:30,541 INFO [main-SendThread(zk-server-4:2181)] org.apache.zookeeper.ClientCnxn: Opening socket connection to server zk-server-4:2181. Will not attempt to authenticate using SASL (unknown error)
> 2017-11-25 15:26:30,541 INFO [main-SendThread(zk-server-4:2181)] org.apache.zookeeper.ClientCnxn: Socket connection established to zk-server-4:2181, initiating session
> 2017-11-25 15:26:30,812 INFO [main-SendThread(zk-server-4:2181)] org.apache.zookeeper.ClientCnxn: Session establishment complete on server zk-server-4:2181, sessionid = 0x55cf8f81ebd7f1a, negotiated timeout = 12000
> 2017-11-25 15:26:30,812 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager: State change: RECONNECTED
> {noformat}
> Error logs in zk-server-5:
> {noformat}
> 2017-11-25 15:26:30,825 [myid:5] - INFO  [ProcessThread(sid:5 cport:-1)::PrepRequestProcessor@645] - Got user-level KeeperException when processing sessionid:0x55cf8f81ebd7f1a type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a Error Path:null Error:KeeperErrorCode = Session moved
> 2017-11-25 15:26:30,831 [myid:5] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@357] - caught end of stream exception
> EndOfStreamException: Unable to read additional data from client sessionid 0x55cf8f81ebd7f1a, likely client has closed socket
>         at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
>         at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
>         at java.lang.Thread.run(Thread.java:834)
> 2017-11-25 15:26:30,831 [myid:5] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed socket connection for client /xxx:22014 which had sessionid 0x55cf8f81ebd7f1a
> 2017-11-25 15:26:31,472 [myid:5] - INFO  [ProcessThread(sid:5 cport:-1)::PrepRequestProcessor@645] - Got user-level KeeperException when processing sessionid:0x55cf8f81ebd7f1a type:sync: cxid:0x1ca4e zxid:0xfffffffffffffffe txntype:unknown reqpath:/ Error Path:null Error:KeeperErrorCode = Session moved
> 2017-11-25 15:26:31,472 [myid:5] - INFO  [ProcessThread(sid:5 cport:-1)::PrepRequestProcessor@645] - Got user-level KeeperException when processing sessionid:0x55cf8f81ebd7f1a ty
> pe:sync: cxid:0x1ca4e zxid:0xfffffffffffffffe txntype:unknown reqpath:/ Error Path:null Error:KeeperErrorCode = Session moved
> 2017-11-25 15:30:07,883 [myid:5] - INFO  [ProcessThread(sid:5 cport:-1)::PrepRequestProcessor@592] - Got user-level KeeperException when processing sessionid:0x55cf8f81ebd7f1a type:multi cxid:0x1ca50 zxid:0x1195f7975 txntype:-1 reqpath:n/a aborting remaining multi ops. Error Path:null Error:KeeperErrorCode = Session moved
> 2017-11-25 15:30:08,886 [myid:5] - INFO  [ProcessThread(sid:5 cport:-1)::PrepRequestProcessor@592] - Got user-level KeeperException when processing sessionid:0x55cf8f81ebd7f1a type:multi cxid:0x1ca51 zxid:0x1195f79a5 txntype:-1 reqpath:n/a aborting remaining multi ops. Error Path:null Error:KeeperErrorCode = Session moved
> 2017-11-25 15:30:09,888 [myid:5] - INFO  [ProcessThread(sid:5 cport:-1)::PrepRequestProcessor@592] - Got user-level KeeperException when processing sessionid:0x55cf8f81ebd7f1a type:multi cxid:0x1ca52 zxid:0x1195f79cf txntype:-1 reqpath:n/a aborting remaining multi ops. Error Path:null Error:KeeperErrorCode = Session moved
> ...
> {noformat}


--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

---------------------------------------------------------------------
To unsubscribe, e-mail: yarn-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: yarn-issues-help@hadoop.apache.org