You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Raghav <ra...@gmail.com> on 2018/05/29 14:39:03 UTC
ZooKeeper gets a bind exception: Leader Election Fails
Hi
We have a 3 node zk ensemble. On all three nodes, we see following logs
that indicate that ZK can't bind to port 3888, and after three tries it
gives up. See the logs and highlighted in bold. Subsequently, ZK prints log
"*As I'm leaving the listener thread, I won't be able to participate in
leader election any longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*".
ZK was gracefully shutdown atleast 15 minutes before restarting again. We
can rule out that anything was using that port already.
Any help is greatly appreciated.
**************************************************************************************************
2018-05-28_07:38:56.15336 2018-05-28 07:38:56,148 [myid:] - INFO
[main:QuorumPeerConfig@136] - Reading configuration from:
conf/zoo.cfg
2018-05-28_07:38:56.18385 2018-05-28 07:38:56,183 [myid:] - INFO
[main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.144 to
address: /1.1.1.144 2018-05-28_07:38:56.18643
2018-05-28 07:38:56,184 [myid:] - INFO [main:QuorumPeer$QuorumServer@184]
- Resolved hostname: 1.1.1.143 to address: /1.1.1.143
2018-05-28_07:38:56.18666 2018-05-28 07:38:56,186 [myid:] - INFO
[main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.142 to
address: /1.1.1.142 2018-05-28_07:38:56.18700
2018-05-28 07:38:56,186 [myid:] - INFO [main:QuorumPeerConfig@398] -
Defaulting to majority
quorums
2018-05-28_07:38:56.19613 2018-05-28 07:38:56,195 [myid:2] - INFO
[main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to
200 2018-05-28_07:38:56.19634
2018-05-28 07:38:56,196 [myid:2] - INFO [main:DatadirCleanupManager@79] -
autopurge.purgeInterval set to
24 2018-05-28_07:38:56.19835
2018-05-28 07:38:56,198 [myid:2] - INFO
[PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task
started. 2018-05-28_07:38:56.21229
2018-05-28 07:38:56,212 [myid:2] - INFO
[PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
2018-05-28_07:38:56.34200 2018-05-28 07:38:56,341 [myid:2] - INFO
[main:QuorumPeerMain@130] - Starting quorum
peer
2018-05-28_07:38:56.34870 2018-05-28 07:38:56,348 [myid:2] - INFO
[main:ServerCnxnFactory@117] - Using
org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
factory
2018-05-28_07:38:56.35725 2018-05-28 07:38:56,357 [myid:2] - INFO
[main:NIOServerCnxnFactory@89] - binding to port 0.0.0.0/0.0.0.0:2181
2018-05-28_07:38:56.36150 2018-05-28 07:38:56,361 [myid:2] - INFO
[main:QuorumPeer@1158] - tickTime set to
2000
2018-05-28_07:38:56.36181 2018-05-28 07:38:56,361 [myid:2] - INFO
[main:QuorumPeer@1204] - initLimit set to
10
2018-05-28_07:38:56.36211 2018-05-28 07:38:56,361 [myid:2] - INFO
[main:QuorumPeer@1178] - minSessionTimeout set to
-1
2018-05-28_07:38:56.36411 2018-05-28 07:38:56,362 [myid:2] - INFO
[main:QuorumPeer@1189] - maxSessionTimeout set to
-1
2018-05-28_07:38:56.37134 2018-05-28 07:38:56,371 [myid:2] - INFO
[main:QuorumPeer@1467] - QuorumPeer communication is not
secured!
2018-05-28_07:38:56.37161 2018-05-28 07:38:56,371 [myid:2] - INFO
[main:QuorumPeer@1496] - quorum.cnxn.threads.size set to 20
2018-05-28_07:38:57.09036 2018-05-28 07:38:57,090 [myid:2] - INFO
[ListenerThread:QuorumCnxManager$Listener@736] - My election bind port: /
1.1.1.143:3888
2018-05-28_07:38:57.09877 2018-05-28 07:38:57,091 [myid:2] - ERROR
[/1.1.1.143:3888:QuorumCnxManager$Listener@760] -
*Exception while listening2018-05-28_07:38:57.09878 java.net.BindException:
Cannot assign requested address*
2018-05-28_07:38:57.09878 at
java.net.PlainSocketImpl.socketBind(Native Method)
2018-05-28_07:38:57.09878 at
java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:382)
2018-05-28_07:38:57.09878 at
java.net.ServerSocket.bind(ServerSocket.java:375)
2018-05-28_07:38:57.09878 at
java.net.ServerSocket.bind(ServerSocket.java:329)
2018-05-28_07:38:57.09879 at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:739)
2018-05-28_07:38:57.10491 2018-05-28 07:38:57,104 [myid:2] - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@909] - LOOKING
2018-05-28_07:38:57.10613 2018-05-28 07:38:57,106 [myid:2] - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@813] - New
election. My id = 2, proposed zxid=0x9000023ff
.
.
.
.
2018-05-28_07:38:59.10092 2018-05-28 07:38:59,100 [myid:2] - ERROR
[/1.1.1.143:3888:QuorumCnxManager$Listener@760] - Exception while
listening 2018-05-28_07:38:59.10093
*java.net.BindException:
Cannot assign requested address*
2018-05-28_07:38:59.10093 at
java.net.PlainSocketImpl.socketBind(Native
Method)
2018-05-28_07:38:59.10093 at
java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:382)
2018-05-28_07:38:59.10093 at
java.net.ServerSocket.bind(ServerSocket.java:375)
2018-05-28_07:38:59.10094 at
java.net.ServerSocket.bind(ServerSocket.java:329)
2018-05-28_07:38:59.10094 at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:739)
2018-05-28_07:39:00.10155 2018-05-28 07:39:00,101 [myid:2] - INFO
[/1.1.1.143:3888:QuorumCnxManager$Listener@773] - Leaving
listener
2018-05-28_07:39:00.10186 2018-05-28 07:39:00,101 [myid:2] - ERROR
[/1.1.1.143:3888:QuorumCnxManager$Listener@775] - *As I'm leaving the
listener thread, I won't be able to participate in leader election any
longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*
R
Re: ZooKeeper gets a bind exception: Leader Election Fails
Posted by Andor Molnar <an...@cloudera.com>.
Hi Raghav,
Would you please attach the full logs and config files of all 3 nodes, so
that we could getter better insight of your setup?
Regards,
Andor
On Tue, May 29, 2018 at 6:23 PM, Raghav <ra...@gmail.com> wrote:
> Ben
>
> So there are scripts that performed the stop and restart for us. Between
> stop and restart there was 15 minutes of difference.
>
> Could it be possible that previous instance of zk didn't close cleanly and
> that left 3888 to be busy and not available for the new instance ?
>
> I used "lsof -i :3888" to check and I can't see anything at the moment. Am
> I missing anything ?
>
> Thanks for your help.
>
> On Tue, May 29, 2018 at 8:49 AM, Ben Wood <bw...@mesosphere.io> wrote:
>
> > Just to double check, you confirmed via netstat (or similar) that nothing
> > is using the port, correct?
> >
> > On Tue, May 29, 2018 at 7:39 AM, Raghav <ra...@gmail.com> wrote:
> >
> > > Hi
> > >
> > > We have a 3 node zk ensemble. On all three nodes, we see following logs
> > > that indicate that ZK can't bind to port 3888, and after three tries it
> > > gives up. See the logs and highlighted in bold. Subsequently, ZK prints
> > log
> > > "*As I'm leaving the listener thread, I won't be able to participate in
> > > leader election any longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*".
> > >
> > > ZK was gracefully shutdown atleast 15 minutes before restarting again.
> We
> > > can rule out that anything was using that port already.
> > >
> > > Any help is greatly appreciated.
> > >
> > > ************************************************************
> > > **************************************
> > > 2018-05-28_07:38:56.15336 2018-05-28 07:38:56,148 [myid:] - INFO
> > > [main:QuorumPeerConfig@136] - Reading configuration from:
> > > conf/zoo.cfg
> > > 2018-05-28_07:38:56.18385 2018-05-28 07:38:56,183 [myid:] - INFO
> > > [main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.144 to
> > > address: /1.1.1.144 2018-05-28_07:38:56.18643
> > > 2018-05-28 07:38:56,184 [myid:] - INFO [main:QuorumPeer$QuorumServer@
> > 184]
> > > - Resolved hostname: 1.1.1.143 to address: /1.1.1.143
> > > 2018-05-28_07:38:56.18666 2018-05-28 07:38:56,186 [myid:] - INFO
> > > [main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.142 to
> > > address: /1.1.1.142 2018-05-28_07:38:56.18700
> > > 2018-05-28 07:38:56,186 [myid:] - INFO [main:QuorumPeerConfig@398] -
> > > Defaulting to majority
> > > quorums
> > > 2018-05-28_07:38:56.19613 2018-05-28 07:38:56,195 [myid:2] - INFO
> > > [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to
> > > 200 2018-05-28_07:38:56.19634
> > > 2018-05-28 07:38:56,196 [myid:2] - INFO [main:DatadirCleanupManager@79
> ]
> > -
> > > autopurge.purgeInterval set to
> > > 24 2018-05-28_07:38:56.19835
> > > 2018-05-28 07:38:56,198 [myid:2] - INFO
> > > [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task
> > > started.
> > 2018-05-28_07:38:56.21229
> > > 2018-05-28 07:38:56,212 [myid:2] - INFO
> > > [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task
> completed.
> > > 2018-05-28_07:38:56.34200 2018-05-28 07:38:56,341 [myid:2] - INFO
> > > [main:QuorumPeerMain@130] - Starting quorum
> > > peer
> > > 2018-05-28_07:38:56.34870 2018-05-28 07:38:56,348 [myid:2] - INFO
> > > [main:ServerCnxnFactory@117] - Using
> > > org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
> > > factory
> > > 2018-05-28_07:38:56.35725 2018-05-28 07:38:56,357 [myid:2] - INFO
> > > [main:NIOServerCnxnFactory@89] - binding to port 0.0.0.0/0.0.0.0:2181
> > > 2018-05-28_07:38:56.36150 2018-05-28 07:38:56,361 [myid:2] - INFO
> > > [main:QuorumPeer@1158] - tickTime set to
> > > 2000
> > > 2018-05-28_07:38:56.36181 2018-05-28 07:38:56,361 [myid:2] - INFO
> > > [main:QuorumPeer@1204] - initLimit set to
> > > 10
> > > 2018-05-28_07:38:56.36211 2018-05-28 07:38:56,361 [myid:2] - INFO
> > > [main:QuorumPeer@1178] - minSessionTimeout set to
> > > -1
> > > 2018-05-28_07:38:56.36411 2018-05-28 07:38:56,362 [myid:2] - INFO
> > > [main:QuorumPeer@1189] - maxSessionTimeout set to
> > > -1
> > > 2018-05-28_07:38:56.37134 2018-05-28 07:38:56,371 [myid:2] - INFO
> > > [main:QuorumPeer@1467] - QuorumPeer communication is not
> > > secured!
> > > 2018-05-28_07:38:56.37161 2018-05-28 07:38:56,371 [myid:2] - INFO
> > > [main:QuorumPeer@1496] - quorum.cnxn.threads.size set to 20
> > > 2018-05-28_07:38:57.09036 2018-05-28 07:38:57,090 [myid:2] - INFO
> > > [ListenerThread:QuorumCnxManager$Listener@736] - My election bind
> port:
> > /
> > > 1.1.1.143:3888
> > > 2018-05-28_07:38:57.09877 2018-05-28 07:38:57,091 [myid:2] - ERROR
> > > [/1.1.1.143:3888:QuorumCnxManager$Listener@760] -
> > > *Exception while listening2018-05-28_07:38:57.09878
> > > java.net.BindException:
> > > Cannot assign requested address*
> > > 2018-05-28_07:38:57.09878 at
> > > java.net.PlainSocketImpl.socketBind(Native Method)
> > > 2018-05-28_07:38:57.09878 at
> > > java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:
> 382)
> > > 2018-05-28_07:38:57.09878 at
> > > java.net.ServerSocket.bind(ServerSocket.java:375)
> > > 2018-05-28_07:38:57.09878 at
> > > java.net.ServerSocket.bind(ServerSocket.java:329)
> > > 2018-05-28_07:38:57.09879 at
> > > org.apache.zookeeper.server.quorum.QuorumCnxManager$
> > > Listener.run(QuorumCnxManager.java:739)
> > > 2018-05-28_07:38:57.10491 2018-05-28 07:38:57,104 [myid:2] - INFO
> > > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@909] - LOOKING
> > > 2018-05-28_07:38:57.10613 2018-05-28 07:38:57,106 [myid:2] - INFO
> > > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@813] - New
> > > election. My id = 2, proposed zxid=0x9000023ff
> > >
> > >
> > >
> > > .
> > > .
> > > .
> > > .
> > >
> > >
> > >
> > > 2018-05-28_07:38:59.10092 2018-05-28 07:38:59,100 [myid:2] - ERROR
> > > [/1.1.1.143:3888:QuorumCnxManager$Listener@760] - Exception while
> > > listening 2018-05-28_07:38:59.10093
> > > *java.net.BindException:
> > > Cannot assign requested address*
> > > 2018-05-28_07:38:59.10093 at
> > > java.net.PlainSocketImpl.socketBind(Native
> > > Method)
> > > 2018-05-28_07:38:59.10093 at
> > > java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:
> 382)
> > > 2018-05-28_07:38:59.10093 at
> > > java.net.ServerSocket.bind(ServerSocket.java:375)
> > > 2018-05-28_07:38:59.10094 at
> > > java.net.ServerSocket.bind(ServerSocket.java:329)
> > > 2018-05-28_07:38:59.10094 at
> > > org.apache.zookeeper.server.quorum.QuorumCnxManager$
> > > Listener.run(QuorumCnxManager.java:739)
> > > 2018-05-28_07:39:00.10155 2018-05-28 07:39:00,101 [myid:2] - INFO
> > > [/1.1.1.143:3888:QuorumCnxManager$Listener@773] - Leaving
> > > listener
> > > 2018-05-28_07:39:00.10186 2018-05-28 07:39:00,101 [myid:2] - ERROR
> > > [/1.1.1.143:3888:QuorumCnxManager$Listener@775] - *As I'm leaving the
> > > listener thread, I won't be able to participate in leader election any
> > > longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*
> > >
> > >
> > >
> > > R
> > >
> >
> >
> >
> > --
> > Ben Wood
> > Software Engineer - Data Agility
> > Mesosphere
> >
>
>
>
> --
> Raghav
>
Re: ZooKeeper gets a bind exception: Leader Election Fails
Posted by Raghav <ra...@gmail.com>.
Ben
So there are scripts that performed the stop and restart for us. Between
stop and restart there was 15 minutes of difference.
Could it be possible that previous instance of zk didn't close cleanly and
that left 3888 to be busy and not available for the new instance ?
I used "lsof -i :3888" to check and I can't see anything at the moment. Am
I missing anything ?
Thanks for your help.
On Tue, May 29, 2018 at 8:49 AM, Ben Wood <bw...@mesosphere.io> wrote:
> Just to double check, you confirmed via netstat (or similar) that nothing
> is using the port, correct?
>
> On Tue, May 29, 2018 at 7:39 AM, Raghav <ra...@gmail.com> wrote:
>
> > Hi
> >
> > We have a 3 node zk ensemble. On all three nodes, we see following logs
> > that indicate that ZK can't bind to port 3888, and after three tries it
> > gives up. See the logs and highlighted in bold. Subsequently, ZK prints
> log
> > "*As I'm leaving the listener thread, I won't be able to participate in
> > leader election any longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*".
> >
> > ZK was gracefully shutdown atleast 15 minutes before restarting again. We
> > can rule out that anything was using that port already.
> >
> > Any help is greatly appreciated.
> >
> > ************************************************************
> > **************************************
> > 2018-05-28_07:38:56.15336 2018-05-28 07:38:56,148 [myid:] - INFO
> > [main:QuorumPeerConfig@136] - Reading configuration from:
> > conf/zoo.cfg
> > 2018-05-28_07:38:56.18385 2018-05-28 07:38:56,183 [myid:] - INFO
> > [main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.144 to
> > address: /1.1.1.144 2018-05-28_07:38:56.18643
> > 2018-05-28 07:38:56,184 [myid:] - INFO [main:QuorumPeer$QuorumServer@
> 184]
> > - Resolved hostname: 1.1.1.143 to address: /1.1.1.143
> > 2018-05-28_07:38:56.18666 2018-05-28 07:38:56,186 [myid:] - INFO
> > [main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.142 to
> > address: /1.1.1.142 2018-05-28_07:38:56.18700
> > 2018-05-28 07:38:56,186 [myid:] - INFO [main:QuorumPeerConfig@398] -
> > Defaulting to majority
> > quorums
> > 2018-05-28_07:38:56.19613 2018-05-28 07:38:56,195 [myid:2] - INFO
> > [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to
> > 200 2018-05-28_07:38:56.19634
> > 2018-05-28 07:38:56,196 [myid:2] - INFO [main:DatadirCleanupManager@79]
> -
> > autopurge.purgeInterval set to
> > 24 2018-05-28_07:38:56.19835
> > 2018-05-28 07:38:56,198 [myid:2] - INFO
> > [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task
> > started.
> 2018-05-28_07:38:56.21229
> > 2018-05-28 07:38:56,212 [myid:2] - INFO
> > [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
> > 2018-05-28_07:38:56.34200 2018-05-28 07:38:56,341 [myid:2] - INFO
> > [main:QuorumPeerMain@130] - Starting quorum
> > peer
> > 2018-05-28_07:38:56.34870 2018-05-28 07:38:56,348 [myid:2] - INFO
> > [main:ServerCnxnFactory@117] - Using
> > org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
> > factory
> > 2018-05-28_07:38:56.35725 2018-05-28 07:38:56,357 [myid:2] - INFO
> > [main:NIOServerCnxnFactory@89] - binding to port 0.0.0.0/0.0.0.0:2181
> > 2018-05-28_07:38:56.36150 2018-05-28 07:38:56,361 [myid:2] - INFO
> > [main:QuorumPeer@1158] - tickTime set to
> > 2000
> > 2018-05-28_07:38:56.36181 2018-05-28 07:38:56,361 [myid:2] - INFO
> > [main:QuorumPeer@1204] - initLimit set to
> > 10
> > 2018-05-28_07:38:56.36211 2018-05-28 07:38:56,361 [myid:2] - INFO
> > [main:QuorumPeer@1178] - minSessionTimeout set to
> > -1
> > 2018-05-28_07:38:56.36411 2018-05-28 07:38:56,362 [myid:2] - INFO
> > [main:QuorumPeer@1189] - maxSessionTimeout set to
> > -1
> > 2018-05-28_07:38:56.37134 2018-05-28 07:38:56,371 [myid:2] - INFO
> > [main:QuorumPeer@1467] - QuorumPeer communication is not
> > secured!
> > 2018-05-28_07:38:56.37161 2018-05-28 07:38:56,371 [myid:2] - INFO
> > [main:QuorumPeer@1496] - quorum.cnxn.threads.size set to 20
> > 2018-05-28_07:38:57.09036 2018-05-28 07:38:57,090 [myid:2] - INFO
> > [ListenerThread:QuorumCnxManager$Listener@736] - My election bind port:
> /
> > 1.1.1.143:3888
> > 2018-05-28_07:38:57.09877 2018-05-28 07:38:57,091 [myid:2] - ERROR
> > [/1.1.1.143:3888:QuorumCnxManager$Listener@760] -
> > *Exception while listening2018-05-28_07:38:57.09878
> > java.net.BindException:
> > Cannot assign requested address*
> > 2018-05-28_07:38:57.09878 at
> > java.net.PlainSocketImpl.socketBind(Native Method)
> > 2018-05-28_07:38:57.09878 at
> > java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:382)
> > 2018-05-28_07:38:57.09878 at
> > java.net.ServerSocket.bind(ServerSocket.java:375)
> > 2018-05-28_07:38:57.09878 at
> > java.net.ServerSocket.bind(ServerSocket.java:329)
> > 2018-05-28_07:38:57.09879 at
> > org.apache.zookeeper.server.quorum.QuorumCnxManager$
> > Listener.run(QuorumCnxManager.java:739)
> > 2018-05-28_07:38:57.10491 2018-05-28 07:38:57,104 [myid:2] - INFO
> > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@909] - LOOKING
> > 2018-05-28_07:38:57.10613 2018-05-28 07:38:57,106 [myid:2] - INFO
> > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@813] - New
> > election. My id = 2, proposed zxid=0x9000023ff
> >
> >
> >
> > .
> > .
> > .
> > .
> >
> >
> >
> > 2018-05-28_07:38:59.10092 2018-05-28 07:38:59,100 [myid:2] - ERROR
> > [/1.1.1.143:3888:QuorumCnxManager$Listener@760] - Exception while
> > listening 2018-05-28_07:38:59.10093
> > *java.net.BindException:
> > Cannot assign requested address*
> > 2018-05-28_07:38:59.10093 at
> > java.net.PlainSocketImpl.socketBind(Native
> > Method)
> > 2018-05-28_07:38:59.10093 at
> > java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:382)
> > 2018-05-28_07:38:59.10093 at
> > java.net.ServerSocket.bind(ServerSocket.java:375)
> > 2018-05-28_07:38:59.10094 at
> > java.net.ServerSocket.bind(ServerSocket.java:329)
> > 2018-05-28_07:38:59.10094 at
> > org.apache.zookeeper.server.quorum.QuorumCnxManager$
> > Listener.run(QuorumCnxManager.java:739)
> > 2018-05-28_07:39:00.10155 2018-05-28 07:39:00,101 [myid:2] - INFO
> > [/1.1.1.143:3888:QuorumCnxManager$Listener@773] - Leaving
> > listener
> > 2018-05-28_07:39:00.10186 2018-05-28 07:39:00,101 [myid:2] - ERROR
> > [/1.1.1.143:3888:QuorumCnxManager$Listener@775] - *As I'm leaving the
> > listener thread, I won't be able to participate in leader election any
> > longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*
> >
> >
> >
> > R
> >
>
>
>
> --
> Ben Wood
> Software Engineer - Data Agility
> Mesosphere
>
--
Raghav
Re: ZooKeeper gets a bind exception: Leader Election Fails
Posted by Ben Wood <bw...@mesosphere.io>.
Just to double check, you confirmed via netstat (or similar) that nothing
is using the port, correct?
On Tue, May 29, 2018 at 7:39 AM, Raghav <ra...@gmail.com> wrote:
> Hi
>
> We have a 3 node zk ensemble. On all three nodes, we see following logs
> that indicate that ZK can't bind to port 3888, and after three tries it
> gives up. See the logs and highlighted in bold. Subsequently, ZK prints log
> "*As I'm leaving the listener thread, I won't be able to participate in
> leader election any longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*".
>
> ZK was gracefully shutdown atleast 15 minutes before restarting again. We
> can rule out that anything was using that port already.
>
> Any help is greatly appreciated.
>
> ************************************************************
> **************************************
> 2018-05-28_07:38:56.15336 2018-05-28 07:38:56,148 [myid:] - INFO
> [main:QuorumPeerConfig@136] - Reading configuration from:
> conf/zoo.cfg
> 2018-05-28_07:38:56.18385 2018-05-28 07:38:56,183 [myid:] - INFO
> [main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.144 to
> address: /1.1.1.144 2018-05-28_07:38:56.18643
> 2018-05-28 07:38:56,184 [myid:] - INFO [main:QuorumPeer$QuorumServer@184]
> - Resolved hostname: 1.1.1.143 to address: /1.1.1.143
> 2018-05-28_07:38:56.18666 2018-05-28 07:38:56,186 [myid:] - INFO
> [main:QuorumPeer$QuorumServer@184] - Resolved hostname: 1.1.1.142 to
> address: /1.1.1.142 2018-05-28_07:38:56.18700
> 2018-05-28 07:38:56,186 [myid:] - INFO [main:QuorumPeerConfig@398] -
> Defaulting to majority
> quorums
> 2018-05-28_07:38:56.19613 2018-05-28 07:38:56,195 [myid:2] - INFO
> [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to
> 200 2018-05-28_07:38:56.19634
> 2018-05-28 07:38:56,196 [myid:2] - INFO [main:DatadirCleanupManager@79] -
> autopurge.purgeInterval set to
> 24 2018-05-28_07:38:56.19835
> 2018-05-28 07:38:56,198 [myid:2] - INFO
> [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task
> started. 2018-05-28_07:38:56.21229
> 2018-05-28 07:38:56,212 [myid:2] - INFO
> [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
> 2018-05-28_07:38:56.34200 2018-05-28 07:38:56,341 [myid:2] - INFO
> [main:QuorumPeerMain@130] - Starting quorum
> peer
> 2018-05-28_07:38:56.34870 2018-05-28 07:38:56,348 [myid:2] - INFO
> [main:ServerCnxnFactory@117] - Using
> org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
> factory
> 2018-05-28_07:38:56.35725 2018-05-28 07:38:56,357 [myid:2] - INFO
> [main:NIOServerCnxnFactory@89] - binding to port 0.0.0.0/0.0.0.0:2181
> 2018-05-28_07:38:56.36150 2018-05-28 07:38:56,361 [myid:2] - INFO
> [main:QuorumPeer@1158] - tickTime set to
> 2000
> 2018-05-28_07:38:56.36181 2018-05-28 07:38:56,361 [myid:2] - INFO
> [main:QuorumPeer@1204] - initLimit set to
> 10
> 2018-05-28_07:38:56.36211 2018-05-28 07:38:56,361 [myid:2] - INFO
> [main:QuorumPeer@1178] - minSessionTimeout set to
> -1
> 2018-05-28_07:38:56.36411 2018-05-28 07:38:56,362 [myid:2] - INFO
> [main:QuorumPeer@1189] - maxSessionTimeout set to
> -1
> 2018-05-28_07:38:56.37134 2018-05-28 07:38:56,371 [myid:2] - INFO
> [main:QuorumPeer@1467] - QuorumPeer communication is not
> secured!
> 2018-05-28_07:38:56.37161 2018-05-28 07:38:56,371 [myid:2] - INFO
> [main:QuorumPeer@1496] - quorum.cnxn.threads.size set to 20
> 2018-05-28_07:38:57.09036 2018-05-28 07:38:57,090 [myid:2] - INFO
> [ListenerThread:QuorumCnxManager$Listener@736] - My election bind port: /
> 1.1.1.143:3888
> 2018-05-28_07:38:57.09877 2018-05-28 07:38:57,091 [myid:2] - ERROR
> [/1.1.1.143:3888:QuorumCnxManager$Listener@760] -
> *Exception while listening2018-05-28_07:38:57.09878
> java.net.BindException:
> Cannot assign requested address*
> 2018-05-28_07:38:57.09878 at
> java.net.PlainSocketImpl.socketBind(Native Method)
> 2018-05-28_07:38:57.09878 at
> java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:382)
> 2018-05-28_07:38:57.09878 at
> java.net.ServerSocket.bind(ServerSocket.java:375)
> 2018-05-28_07:38:57.09878 at
> java.net.ServerSocket.bind(ServerSocket.java:329)
> 2018-05-28_07:38:57.09879 at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$
> Listener.run(QuorumCnxManager.java:739)
> 2018-05-28_07:38:57.10491 2018-05-28 07:38:57,104 [myid:2] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@909] - LOOKING
> 2018-05-28_07:38:57.10613 2018-05-28 07:38:57,106 [myid:2] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@813] - New
> election. My id = 2, proposed zxid=0x9000023ff
>
>
>
> .
> .
> .
> .
>
>
>
> 2018-05-28_07:38:59.10092 2018-05-28 07:38:59,100 [myid:2] - ERROR
> [/1.1.1.143:3888:QuorumCnxManager$Listener@760] - Exception while
> listening 2018-05-28_07:38:59.10093
> *java.net.BindException:
> Cannot assign requested address*
> 2018-05-28_07:38:59.10093 at
> java.net.PlainSocketImpl.socketBind(Native
> Method)
> 2018-05-28_07:38:59.10093 at
> java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:382)
> 2018-05-28_07:38:59.10093 at
> java.net.ServerSocket.bind(ServerSocket.java:375)
> 2018-05-28_07:38:59.10094 at
> java.net.ServerSocket.bind(ServerSocket.java:329)
> 2018-05-28_07:38:59.10094 at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$
> Listener.run(QuorumCnxManager.java:739)
> 2018-05-28_07:39:00.10155 2018-05-28 07:39:00,101 [myid:2] - INFO
> [/1.1.1.143:3888:QuorumCnxManager$Listener@773] - Leaving
> listener
> 2018-05-28_07:39:00.10186 2018-05-28 07:39:00,101 [myid:2] - ERROR
> [/1.1.1.143:3888:QuorumCnxManager$Listener@775] - *As I'm leaving the
> listener thread, I won't be able to participate in leader election any
> longer: /1.1.1.143:3888 <http://1.1.1.143:3888>*
>
>
>
> R
>
--
Ben Wood
Software Engineer - Data Agility
Mesosphere