Mailing-List: contact user-help@zookeeper.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@zookeeper.apache.org
Content-Type: text/plain; charset=utf-8
Mime-Version: 1.0 (Mac OS X Mail 8.2 \(2104\))
Subject: Re: Unstable work of zookeeper
From: Flavio Junqueira <fpj@apache.org>
In-Reply-To: <568AD511-F4AD-42EF-A964-DADCB0B0DAAC@icloud.com>
Date: Thu, 24 Sep 2015 06:36:07 -0700
Content-Transfer-Encoding: quoted-printable
Message-Id: <DA39A327-B103-4F79-B14C-EEC30AC5DC1D@apache.org>
References: <568AD511-F4AD-42EF-A964-DADCB0B0DAAC@icloud.com>
To: user@zookeeper.apache.org

I can see that the client is disconnecting from the server, and there is =
also a new round of leader election for the zookeeper servers. If this =
is happening, then yeah, your ensemble is unstable. If the ensemble =
leader election is being triggered frequently, then I'd start by looking =
there. Try to determine why the ensemble is failing to continue with the =
same leader. If ensemble elections aren't happening frequently, then =
another possibility is that GC pauses are causing the session to expire.

-Flavio

> On 24 Sep 2015, at 05:24, Akmal Abbasov <akmal.abbasov@icloud.com> =
wrote:
>=20
> Hi,
> I am using zookeeper 3.4.6
> I have a spark cluster configured with HA. Once per 1-2 days, the =
active spark master is shutting down with a message
> 15/09/23 18:58:18 INFO zookeeper.ClientCnxn: Unable to read additional =
data from server sessionid 0x34ffa68dbd10021, likely server has closed =
socket, closing socket connection and attempting reconnect
> 15/09/23 18:58:18 INFO state.ConnectionStateManager: State change: =
SUSPENDED
> 15/09/23 18:58:18 INFO master.ZooKeeperLeaderElectionAgent: We have =
lost leadership
> 15/09/23 18:58:18 ERROR master.Master: Leadership has been revoked -- =
master shutting down.
> 15/09/23 18:58:18 INFO util.Utils: Shutdown hook called
>=20
> I don=E2=80=99t have the zookeeper logs from the same period, but the =
logs are full of the these messages=20
> 2015-09-24 05:07:42,228 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - =
Accepted socket connection from /10.0.8.4:34705
> 2015-09-24 05:07:42,229 [myid:1] - WARN  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - =
Connection request from old client /10.0.8.4:34705; will be dropped if =
server is in r-o mode
> 2015-09-24 05:07:42,229 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client =
attempting to establish new session at /10.0.8.4:34705
> 2015-09-24 05:07:42,292 [myid:1] - INFO  =
[CommitProcessor:1:ZooKeeperServer@617] - Established session =
0x14ffd3670130030 with negotiated timeout 20001 for client =
/10.0.8.4:34705
> 2015-09-24 05:07:42,302 [myid:1] - 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 0x14ffd3670130030, 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:745)
> 2015-09-24 05:07:42,303 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed =
socket connection for client /10.0.8.4:34705 which had sessionid =
0x14ffd3670130030
> 2015-09-24 05:07:42,314 [myid:1] - ERROR =
[CommitProcessor:1:NIOServerCnxn@178] - Unexpected Exception:
> java.nio.channels.CancelledKeyException
> 	at =
sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
> 	at =
sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
> 	at =
org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:15=
1)
> 	at =
org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:=
1081)
> 	at =
org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequ=
estProcessor.java:404)
> 	at =
org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.jav=
a:74)
> 2015-09-24 05:07:42,334 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - =
Accepted socket connection from /10.0.8.4:34707
> 2015-09-24 05:07:42,334 [myid:1] - WARN  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - =
Connection request from old client /10.0.8.4:34707; will be dropped if =
server is in r-o mode
> 2015-09-24 05:07:42,335 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client =
attempting to establish new session at /10.0.8.4:34707
> 2015-09-24 05:07:42,357 [myid:1] - INFO  =
[CommitProcessor:1:ZooKeeperServer@617] - Established session =
0x14ffd3670130031 with negotiated timeout 20001 for client =
/10.0.8.4:34707
> 2015-09-24 05:07:42,364 [myid:1] - 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 0x14ffd3670130031, 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:745)
> 2015-09-24 05:07:42,365 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed =
socket connection for client /10.0.8.4:34707 which had sessionid =
0x14ffd3670130031
> 2015-09-24 05:07:42,376 [myid:1] - ERROR =
[CommitProcessor:1:NIOServerCnxn@178] - Unexpected Exception:
> java.nio.channels.CancelledKeyException
> 	at =
sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
> 	at =
sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
> 	at =
org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:15=
1)
> 	at =
org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:=
1081)
> 	at =
org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequ=
estProcessor.java:404)
> 	at =
org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.jav=
a:74)
>=20
> Also there are=20
> 2015-09-24 06:29:54,459 [myid:1] - INFO  =
[QuorumPeer[myid=3D1]/0:0:0:0:0:0:0:0:2181:FollowerZooKeeperServer@139] =
- Shutting down
> 2015-09-24 06:29:54,459 [myid:1] - INFO  =
[QuorumPeer[myid=3D1]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@441] - =
shutting down
> 2015-09-24 06:29:54,459 [myid:1] - INFO  =
[QuorumPeer[myid=3D1]/0:0:0:0:0:0:0:0:2181:FollowerRequestProcessor@105] =
- Shutting down
> 2015-09-24 06:29:54,459 [myid:1] - INFO  =
[FollowerRequestProcessor:1:FollowerRequestProcessor@95] - =
FollowerRequestProcessor exited loop!
> 2015-09-24 06:29:54,460 [myid:1] - INFO  =
[QuorumPeer[myid=3D1]/0:0:0:0:0:0:0:0:2181:CommitProcessor@181] - =
Shutting down
> 2015-09-24 06:29:54,464 [myid:1] - INFO  =
[CommitProcessor:1:CommitProcessor@150] - CommitProcessor exited loop!
> 2015-09-24 06:29:54,465 [myid:1] - INFO  =
[QuorumPeer[myid=3D1]/0:0:0:0:0:0:0:0:2181:FinalRequestProcessor@415] - =
shutdown of request processor complete
> 2015-09-24 06:29:54,466 [myid:1] - INFO  =
[QuorumPeer[myid=3D1]/0:0:0:0:0:0:0:0:2181:SyncRequestProcessor@209] - =
Shutting down
> 2015-09-24 06:29:54,466 [myid:1] - INFO  =
[SyncThread:1:SyncRequestProcessor@187] - SyncRequestProcessor exited!
> 2015-09-24 06:29:54,466 [myid:1] - INFO  =
[QuorumPeer[myid=3D1]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING
> 2015-09-24 06:29:54,584 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - =
Accepted socket connection from /10.0.8.58:36137
> 2015-09-24 06:29:54,584 [myid:1] - WARN  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@362] - =
Exception causing close of session 0x0 due to java.io.IOException: =
ZooKeeperServer not running
> 2015-09-24 06:29:54,584 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed =
socket connection for client /10.0.8.58:36137 (no session established =
for client)
> 2015-09-24 06:29:54,679 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - =
Accepted socket connection from /10.0.8.57:57410
> 2015-09-24 06:29:54,680 [myid:1] - WARN  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@362] - =
Exception causing close of session 0x0 due to java.io.IOException: =
ZooKeeperServer not running
> 2015-09-24 06:29:54,680 [myid:1] - INFO  =
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed =
socket connection for client /10.0.8.57:57410 (no session established =
for client)
>=20
> I also observed that hadoop-zkfc restarts very frequently.
> Any ideas what could be wrong?
>=20
> Thanks.