Home | About | Sematext search-lucene.com search-hadoop.com
 Search Hadoop and all its subprojects:

Switch to Threaded View
Zookeeper >> mail # user >> Random unexpected exception in followers every so often


Copy link to this message
-
Re: Random unexpected exception in followers every so often
Hi Steve, is there any indication what the problem is? The log code
looks like this in Follower.java

            } catch (IOException e) {
                LOG.warn("Exception when following the leader", e);

However I don't see any exception text in log you provided, which is odd.

Patrick
On Thu, Jul 25, 2013 at 10:58 AM, Stephen Tyree <[EMAIL PROTECTED]> wrote:
> Hello all,
>
> In our development Zookeeper cluster, about once a week we've started
> seeing two of the followers have an Unexpected Exception with Zookeeper
> 3.4.5. Looking at the metrics from the mntr four letter word, there is no
> particular amount of load or number of sessions that leads to this
> behavior, it just seems totally out of the blue. Here is a snippet of INFO
> level logs from that period of time (IP addresses have been scrubbed):
>
> 2013-07-25 04:19:20,066 - INFO  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:NIOServerCnxnFactory@197] - Accepted socket
> connection from /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,066 - WARN  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:ZooKeeperServer@793] - Connection request
> from old client /xxx.xxx.xxx.xxx:xxxxx; will be dropped if server is in r-o
> mode
> 2013-07-25 04:19:20,067 - INFO  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:ZooKeeperServer@839] - Client attempting to
> establish new session at /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,068 - INFO  [CommitProcessor:6:ZooKeeperServer@595] -
> Established session 0x63ffea596ee912b with negotiated timeout 30000 for
> client /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,068 - INFO  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:ZooKeeperServer@863] - got auth packet
> /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,068 - INFO  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:ZooKeeperServer@897] - auth success
> /xxx.xxx.xxx.xxx:xxxxx
> (--------lots of normal activity----------)
> 2013-07-25 04:19:20,317 - INFO  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:ZooKeeperServer@839] - Client attempting to
> establish new session at /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,318 - INFO  [CommitProcessor:6:ZooKeeperServer@595] -
> Established session 0x63ffea596ee912c with negotiated timeout 10000 for
> client /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,318 - INFO  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:ZooKeeperServer@863] - got auth packet
> /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,318 - INFO  [NIOServerCxn.Factory:
> 0.0.0.0/xxx.xxx.xxx.xxx:xxxxx:ZooKeeperServer@897] - auth success
> /xxx.xxx.xxx.xxx:xxxxx
> 2013-07-25 04:19:20,319 - WARN
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:Follower@89] - Exception when
> following the leader
> 2013-07-25 04:19:20,319 - INFO
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:Follower@166] - shutdown called
> 2013-07-25 04:19:20,319 - INFO
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:NIOServerCnxn@1001] - Closed
> socket connection for client /xxx.xxx.xxx.xxx:xxxxx which had sessionid
> 0x63ffea596ee8bab
> (-----------One of these for each active session it seems-----------------))
> 2013-07-25 04:19:20,375 - INFO
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:NIOServerCnxn@1001] - Closed
> socket connection for client /xxx.xxx.xxx.xxx:xxxxx which had sessionid
> 0x83fdf0b85832d61
> 2013-07-25 04:19:20,376 - INFO
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:FollowerZooKeeperServer@139] -
> Shutting down
> 2013-07-25 04:19:20,376 - INFO
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@419] - shutting
> down
> 2013-07-25 04:19:20,376 - INFO
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:FollowerRequestProcessor@105] -
> Shutting down
> 2013-07-25 04:19:20,376 - INFO
>  [QuorumPeer[myid=6]/0:0:0:0:0:0:0:0:2181:CommitProcessor@181] - Shutting
> down
> 2013-07-25 04:19:20,376 - INFO
>  [FollowerRequestProcessor:6:FollowerRequestProcessor@95] -
> FollowerRequestProcessor exited loop!
> 2013-07-25 04:19:20,376 - INFO  [CommitProcessor:6:CommitProcessor@150] -