Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: 3.2.1
    • Fix Version/s: None
    • Component/s: quorum
    • Labels:
      None
    • Environment:

      Linux 2.6.9 x86_64

    • Tags:
      Quorum

      Description

      Server fails to join ensemble.

        Activity

        Hide
        Thomas Koch added a comment -

        This issue has not been worked on in the last 20 months, it was reported on ZK 3.2.x and nobody may remember any details about it anymore. I suggest to close it.

        Show
        Thomas Koch added a comment - This issue has not been worked on in the last 20 months, it was reported on ZK 3.2.x and nobody may remember any details about it anymore. I suggest to close it.
        Hide
        Qian Ye added a comment -

        Hi all, some more information about this problem, I find that the status of the election ports of the three working servers is strange. For example, the server 10.23.150.29,

        $ netstat -anp | grep 8888
        (Not all processes could be identified, non-owned process info
        will not be shown, you would have to be root to see it all.)
        tcp 0 0 0.0.0.0:8888 0.0.0.0:* LISTEN -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23933 CLOSE_WAIT -
        tcp 157577 0 10.23.150.29:8888 10.65.27.21:10482 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23929 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23672 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23671 CLOSE_WAIT -
        tcp 41 0 10.23.150.29:8888 10.23.247.141:10790 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23669 CLOSE_WAIT -
        tcp 136 0 10.23.150.29:8888 10.23.247.141:10791 ESTABLISHED -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23668 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23667 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23923 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23666 CLOSE_WAIT -
        tcp 73 0 10.23.150.29:8888 10.23.247.141:10786 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23664 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23663 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23662 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23661 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23660 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23659 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23656 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23651 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23648 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23647 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23646 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23643 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23642 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23640 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23639 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23638 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23637 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23636 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23635 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23634 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23633 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23630 CLOSE_WAIT -
        tcp 6 0 10.23.150.29:8888 10.23.253.43:23620 CLOSE_WAIT -
        tcp 617 0 10.23.150.29:8888 10.65.27.21:28984 CLOSE_WAIT -
        tcp 0 0 10.23.150.29:10593 10.23.253.43:8888 CLOSE_WAIT -
        tcp 51 0 10.23.150.29:8888 10.23.253.43:23712 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23703 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23702 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23699 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23697 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23695 CLOSE_WAIT -
        tcp 1 0 10.23.150.29:8888 10.65.27.21:29185 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23694 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23692 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23690 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23688 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23686 CLOSE_WAIT -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23685 CLOSE_WAIT -
        tcp 0 0 10.23.150.29:8888 10.65.20.68:10581 ESTABLISHED -
        tcp 9 0 10.23.150.29:8888 10.23.253.43:23684 CLOSE_WAIT -

        There are so many socket in the status of CLOSE_WAIT that, the election port cannot accept an extra connection, the maximum of backlog is reached. Notice that most of the recieving queues of these sockets are not empty. It seems that the process is hung somewhere. The other two working server share the same situation. I think there is no other choice but restart the servers to get rid of the trouble, right?

        Show
        Qian Ye added a comment - Hi all, some more information about this problem, I find that the status of the election ports of the three working servers is strange. For example, the server 10.23.150.29, $ netstat -anp | grep 8888 (Not all processes could be identified, non-owned process info will not be shown, you would have to be root to see it all.) tcp 0 0 0.0.0.0:8888 0.0.0.0:* LISTEN - tcp 9 0 10.23.150.29:8888 10.23.253.43:23933 CLOSE_WAIT - tcp 157577 0 10.23.150.29:8888 10.65.27.21:10482 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23929 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23672 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23671 CLOSE_WAIT - tcp 41 0 10.23.150.29:8888 10.23.247.141:10790 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23669 CLOSE_WAIT - tcp 136 0 10.23.150.29:8888 10.23.247.141:10791 ESTABLISHED - tcp 9 0 10.23.150.29:8888 10.23.253.43:23668 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23667 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23923 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23666 CLOSE_WAIT - tcp 73 0 10.23.150.29:8888 10.23.247.141:10786 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23664 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23663 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23662 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23661 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23660 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23659 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23656 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23651 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23648 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23647 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23646 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23643 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23642 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23640 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23639 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23638 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23637 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23636 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23635 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23634 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23633 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23630 CLOSE_WAIT - tcp 6 0 10.23.150.29:8888 10.23.253.43:23620 CLOSE_WAIT - tcp 617 0 10.23.150.29:8888 10.65.27.21:28984 CLOSE_WAIT - tcp 0 0 10.23.150.29:10593 10.23.253.43:8888 CLOSE_WAIT - tcp 51 0 10.23.150.29:8888 10.23.253.43:23712 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23703 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23702 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23699 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23697 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23695 CLOSE_WAIT - tcp 1 0 10.23.150.29:8888 10.65.27.21:29185 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23694 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23692 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23690 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23688 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23686 CLOSE_WAIT - tcp 9 0 10.23.150.29:8888 10.23.253.43:23685 CLOSE_WAIT - tcp 0 0 10.23.150.29:8888 10.65.20.68:10581 ESTABLISHED - tcp 9 0 10.23.150.29:8888 10.23.253.43:23684 CLOSE_WAIT - There are so many socket in the status of CLOSE_WAIT that, the election port cannot accept an extra connection, the maximum of backlog is reached. Notice that most of the recieving queues of these sockets are not empty. It seems that the process is hung somewhere. The other two working server share the same situation. I think there is no other choice but restart the servers to get rid of the trouble, right?
        Hide
        Mahadev konar added a comment -

        qian,

        i read through the logs. what i see is that for server 100 and 201, they are getting votes from the other servers but just missing one. So they get 2 votes from two of the machines (101, 102, 202) and thats why cannot decide on who the leader is. Can you upload the whole log files from these two machine lets say from any similar time frame, so that I can see why this is happening. Is there any chance of a network partition that could have happened? My gut is that this seems like a network problem to me. More logs will help us detect if its really so.

        Also, you might want to use 3.2.2 since it has the most recent bug fixes. It is backwards compatible, so just upgrading one of the servers to 3.2.2 should be fine as well.

        Show
        Mahadev konar added a comment - qian, i read through the logs. what i see is that for server 100 and 201, they are getting votes from the other servers but just missing one. So they get 2 votes from two of the machines (101, 102, 202) and thats why cannot decide on who the leader is. Can you upload the whole log files from these two machine lets say from any similar time frame, so that I can see why this is happening. Is there any chance of a network partition that could have happened? My gut is that this seems like a network problem to me. More logs will help us detect if its really so. Also, you might want to use 3.2.2 since it has the most recent bug fixes. It is backwards compatible, so just upgrading one of the servers to 3.2.2 should be fine as well.
        Hide
        Flavio Junqueira added a comment -

        This message:

        Failed to send last message. Shutting down thread
        
        

        indicates that the server is not being able to send messages. Are you sure they don't have any network issues? Interestingly, it seems that the servers are able to receive connection requests, but not to send messages.

        Show
        Flavio Junqueira added a comment - This message: Failed to send last message. Shutting down thread indicates that the server is not being able to send messages. Are you sure they don't have any network issues? Interestingly, it seems that the servers are able to receive connection requests, but not to send messages.
        Hide
        Flavio Junqueira added a comment -

        I have a quorum with 5 servers, and the configure is as follow

        =============================================

        1. The number of milliseconds of each tick
          tickTime=2000
        2. The number of ticks that the initial
        3. synchronization phase can take
          initLimit=5
        4. The number of ticks that can pass between
        5. sending a request and getting an acknowledgement
          syncLimit=2
        6. the directory where the snapshot is stored.
          dataDir=./data/
        7. the port at which the clients will connect
          clientPort=8181
        1. zookeeper cluster list
          server.100=10.23.253.43:8887:8888
          server.101=10.23.150.29:8887:8888
          server.102=10.23.247.141:8887:8888
          server.200=10.65.20.68:8887:8888
          server.201=10.65.27.21:8887:8888
          ==============================================

        on Jun 15th, data on two of them, server.100 and server.201, were corrupt due to a network adjustment. The result was that the two servers stayed in the election loop and never went out. The log

        shows that the corrupt data generated a error zxid.

        ======>logs from server.100<======
        2010-01-16 21:00:17,352 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote
        2010-01-16 21:00:17,353 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (201,100)
        2010-01-16 21:00:17,353 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 100, LOOKING, FOLLOWING, 101
        2010-01-16 21:00:17,354 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 100, LOOKING, LEADING, 200
        2010-01-16 21:00:34,362 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:42103
        2010-01-16 21:00:34,362 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-16 21:00:34,362 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.253.43:8181

        remote=/10.23.250.215:42103]
        2010-01-16 21:00:54,363 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:46338
        2010-01-16 21:00:54,363 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-16 21:00:54,364 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.253.43:8181

        remote=/10.23.250.215:46338]
        2010-01-16 21:01:14,366 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:50894
        2010-01-16 21:01:14,366 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-16 21:01:14,366 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.253.43:8181

        remote=/10.23.250.215:50894]
        2010-01-16 21:01:17,356 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000
        2010-01-16 21:01:17,356 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102,100)
        2010-01-16 21:01:17,356 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 100, 4335573116, 6, 100, LOOKING, LOOKING, 100

        ======>logs from server.201<======
        2010-01-16 21:00:17,864 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote
        2010-01-16 21:00:17,864 - ERROR [Thread-11258:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread.
        2010-01-16 21:00:17,864 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 201, LOOKING, FOLLOWING, 102
        2010-01-16 21:00:17,864 - WARN [Thread-11258:QuorumCnxManager$SendWorker@554] - Send worker leaving thread
        2010-01-16 21:00:17,864 - WARN [Thread-11259:QuorumCnxManager$RecvWorker@621] - Connection broken:
        java.nio.channels.ClosedChannelException
        at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:113)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:156)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:594)
        2010-01-16 21:00:17,864 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 201, LOOKING, LEADING, 200
        2010-01-16 21:00:18,554 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:59369
        2010-01-16 21:00:18,554 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-16 21:00:18,554 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.27.21:8181

        remote=/10.65.7.48:59369]
        2010-01-16 21:00:38,556 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:34969
        2010-01-16 21:00:38,556 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-16 21:00:38,556 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.27.21:8181

        remote=/10.65.7.48:34969]
        2010-01-16 21:00:58,558 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:38935
        2010-01-16 21:00:58,558 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-16 21:00:58,558 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.27.21:8181

        remote=/10.65.7.48:38935]
        2010-01-16 21:01:17,368 - ERROR [Thread-11260:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread.
        2010-01-16 21:01:17,368 - WARN [Thread-11261:QuorumCnxManager$RecvWorker@621] - Connection broken:
        java.nio.channels.ClosedChannelException
        at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:113)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:156)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:594)
        2010-01-16 21:01:17,368 - WARN [Thread-11260:QuorumCnxManager$SendWorker@554] - Send worker leaving thread
        2010-01-16 21:01:17,866 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000
        2010-01-16 21:01:17,867 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 201, 4335618537, 6, 201, LOOKING, LOOKING, 201
        2010-01-16 21:01:17,867 - ERROR [Thread-11262:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread.

        The server.101, server.102 and server.200 seems working well.

        ======>server.101<======
        Zookeeper version: 3.2.1-808558, built on 08/27/2009 18:48 GMT
        Clients:
        ...

        Latency min/avg/max: 0/0/3016
        Received: 190409661
        Sent: 0
        Outstanding: 0
        Zxid: 0x102837dd7
        Mode: follower
        Node count: 397

        ======>server.102<======
        Zookeeper version: 3.2.1-808558, built on 08/27/2009 18:48 GMT
        Clients:
        ...

        Latency min/avg/max: 0/0/1999
        Received: 201910241
        Sent: 0
        Outstanding: 0
        Zxid: 0x102837ddb
        Mode: follower
        Node count: 397

        Zookeeper version: 3.2.1-808558, built on 08/27/2009 18:48 GMT
        Clients:
        ...

        Latency min/avg/max: 0/0/4004
        Received: 318497545
        Sent: 0
        Outstanding: 0
        Zxid: 0x102837ddf
        Mode: leader
        Node count: 397

        It may be caused by this bug https://issues.apache.org/jira/browse/ZOOKEEPER-596. However, the strange thing is that when I clean up the corrupt data, the server.100 and the server.201 still cannot

        join the quorum.

        Try to start server.201

        ======>logs from server.201<======
        2010-01-19 11:00:12,885 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000
        2010-01-19 11:00:12,885 - DEBUG [WorkerSender Thread:QuorumCnxManager@341] - There is a connection for server 102
        2010-01-19 11:00:12,886 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 100
        2010-01-19 11:00:12,886 - WARN [WorkerSender Thread:QuorumCnxManager@336] - Cannot open channel to 100 at election address /10.23.253.43:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:302)
        at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:323)
        at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:296)
        at java.lang.Thread.run(Thread.java:619)
        2010-01-19 11:00:12,887 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 11:00:12,888 - DEBUG [WorkerSender Thread:QuorumCnxManager$SendWorker@468] - Address of remote peer: 101
        2010-01-19 11:00:12,889 - DEBUG [WorkerSender Thread:QuorumCnxManager@341] - There is a connection for server 200
        2010-01-19 11:00:12,889 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@193] - Receive new message.
        2010-01-19 11:00:12,889 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 201, -1, 1, 201, LOOKING, LOOKING, 201
        2010-01-19 11:00:12,889 - WARN [Thread-27:QuorumCnxManager$RecvWorker@621] - Connection broken:
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:594)
        2010-01-19 11:00:12,890 - ERROR [Thread-26:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread.
        2010-01-19 11:00:12,890 - DEBUG [Thread-26:QuorumCnxManager$SendWorker@487] - Calling finish
        2010-01-19 11:00:12,889 - DEBUG [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@465] - id: 201, proposed id: 201, zxid: -1, proposed zxid: -1
        2010-01-19 11:00:12,890 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote
        2010-01-19 11:00:12,891 - WARN [Thread-26:QuorumCnxManager$SendWorker@554] - Send worker leaving thread
        2010-01-19 11:01:12,892 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 0

        ======>logs from server.100<======
        at this time, the server.100 is down

        ======>logs from server.101<======
        2010-01-19 11:00:05,444 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:35215
        2010-01-19 11:00:05,445 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:05,446 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181

        remote=/10.23.250.215:35215]
        2010-01-19 11:00:25,448 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:39165
        2010-01-19 11:00:25,448 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:25,448 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181

        remote=/10.23.250.215:39165]
        2010-01-19 11:00:45,451 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:43705
        2010-01-19 11:00:45,451 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:45,451 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181

        remote=/10.23.250.215:43705]
        2010-01-19 11:01:05,453 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:48062
        2010-01-19 11:01:05,453 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:01:05,453 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChan
        nel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:48062]
        2010-01-19 11:01:25,455 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:52006
        2010-01-19 11:01:25,455 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe

        ======>logs from server.102<======
        2010-01-19 11:00:06,769 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:35661
        2010-01-19 11:00:06,770 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:06,770 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181

        remote=/10.23.250.215:35661]
        2010-01-19 11:00:26,773 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:39617
        2010-01-19 11:00:26,773 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:26,773 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181

        remote=/10.23.250.215:39617]
        2010-01-19 11:00:46,776 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:44160
        2010-01-19 11:00:46,777 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:46,777 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181

        remote=/10.23.250.215:44160]
        2010-01-19 11:01:06,778 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:48506
        2010-01-19 11:01:06,779 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:01:06,779 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181

        remote=/10.23.250.215:48506]
        2010-01-19 11:01:26,781 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:52452
        2010-01-19 11:01:26,781 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:01:26,781 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181

        remote=/10.23.250.215:52452]

        ======>logs from server.200<======
        2010-01-19 11:00:05,586 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:59644
        2010-01-19 11:00:05,586 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:05,587 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181

        remote=/10.65.7.48:59644]
        2010-01-19 11:00:25,589 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:35356
        2010-01-19 11:00:25,589 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:25,590 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181

        remote=/10.65.7.48:35356]
        2010-01-19 11:00:45,592 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:39554
        2010-01-19 11:00:45,592 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:00:45,592 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181

        remote=/10.65.7.48:39554]
        2010-01-19 11:01:05,594 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:44016
        2010-01-19 11:01:05,594 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:01:05,594 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181

        remote=/10.65.7.48:44016]
        2010-01-19 11:01:25,597 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:47944
        2010-01-19 11:01:25,597 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 11:01:25,597 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181

        remote=/10.65.7.48:47944]

        Try to start server.100
        ======>logs from server.201<======
        at this time, the server.201 is down

        ======>logs from server.100<======
        2010-01-19 18:05:37,612 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@579] - New election: -1
        2010-01-19 18:05:37,613 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:37,615 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102,
        100)
        2010-01-19 18:05:37,616 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:37,616 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@193] - Receive new message.
        2010-01-19 18:05:37,617 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101,
        100)
        2010-01-19 18:05:37,617 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:37,618 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 100, -1, 1, 100, LOOKING, LOOKING, 100
        2010-01-19 18:05:37,619 - DEBUG [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@465] - id: 100, proposed id: 100, zxid: -1, proposed zxid: -1
        2010-01-19 18:05:37,619 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote
        2010-01-19 18:05:37,619 - WARN [WorkerSender Thread:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:302)
        at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:323)
        at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:296)
        at java.lang.Thread.run(Thread.java:619)
        2010-01-19 18:05:37,621 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:37,622 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200,
        100)
        [rd@tc-bps-zk00 log]$ cat zookeeper.log
        2010-01-19 18:05:37,547 - INFO [main:QuorumPeerConfig@80] - Reading configuration from: /home/passport/zookeeper/bin/../conf/zoo.cfg
        2010-01-19 18:05:37,552 - INFO [main:QuorumPeerConfig@232] - Defaulting to majority quorums
        2010-01-19 18:05:37,556 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:hiearchy=default
        2010-01-19 18:05:37,557 - DEBUG [main:HierarchyDynamicMBean@254] - postRegister is called.
        2010-01-19 18:05:37,559 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=root
        2010-01-19 18:05:37,559 - DEBUG [main:LoggerDynamicMBean@256] - Adding AppenderMBean for appender named NOTICEFILE
        2010-01-19 18:05:37,562 - DEBUG [main:AppenderDynamicMBean@152] - getMBeanInfo called.
        2010-01-19 18:05:37,562 - DEBUG [main:AppenderDynamicMBean@309] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:appender=NOTICEFILE
        2010-01-19 18:05:37,563 - DEBUG [main:AppenderDynamicMBean@191] - Adding LayoutMBean:NOTICEFILE,layout=org.apache.log4j.PatternLayout
        2010-01-19 18:05:37,565 - DEBUG [main:LayoutDynamicMBean@138] - getMBeanInfo called.
        2010-01-19 18:05:37,565 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:appender=NOTICEFILE,layout=org.apache.log4j.PatternLayout
        2010-01-19 18:05:37,566 - DEBUG [main:LoggerDynamicMBean@256] - Adding AppenderMBean for appender named WARNFILE
        2010-01-19 18:05:37,567 - DEBUG [main:AppenderDynamicMBean@152] - getMBeanInfo called.
        2010-01-19 18:05:37,568 - DEBUG [main:AppenderDynamicMBean@309] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:appender=WARNFILE
        2010-01-19 18:05:37,568 - DEBUG [main:AppenderDynamicMBean@191] - Adding LayoutMBean:WARNFILE,layout=org.apache.log4j.PatternLayout
        2010-01-19 18:05:37,569 - DEBUG [main:LayoutDynamicMBean@138] - getMBeanInfo called.
        2010-01-19 18:05:37,570 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:appender=WARNFILE,layout=org.apache.log4j.PatternLayout
        2010-01-19 18:05:37,571 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [root] as listener.
        2010-01-19 18:05:37,571 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:logger=org.apache.log4j.jmx.LayoutDynamicMBean
        2010-01-19 18:05:37,572 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.LayoutDynamicMBean] as listener.
        2010-01-19 18:05:37,573 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:logger=org.apache.zookeeper.server.quorum.QuorumPeerMain
        2010-01-19 18:05:37,573 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.zookeeper.server.quorum.QuorumPeerMain] as listener.
        2010-01-19 18:05:37,573 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:logger=org.apache.log4j.jmx.LoggerDynamicMBean
        2010-01-19 18:05:37,574 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.LoggerDynamicMBean] as listener.
        2010-01-19 18:05:37,574 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:logger=org.apache.zookeeper.server.quorum.QuorumPeerConfig
        2010-01-19 18:05:37,574 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.zookeeper.server.quorum.QuorumPeerConfig] as listener.
        2010-01-19 18:05:37,575 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:logger=org.apache.log4j.jmx.HierarchyDynamicMBean
        2010-01-19 18:05:37,575 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.HierarchyDynamicMBean] as listener.
        2010-01-19 18:05:37,575 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75,

        name=log4j:logger=org.apache.log4j.jmx.AppenderDynamicMBean
        2010-01-19 18:05:37,576 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.AppenderDynamicMBean] as listener.
        2010-01-19 18:05:37,576 - INFO [main:QuorumPeerMain@118] - Starting quorum peer
        2010-01-19 18:05:37,602 - INFO [Thread-1:QuorumCnxManager$Listener@409] - My election bind port: 8888
        2010-01-19 18:05:37,604 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumPeer@451] - Starting quorum peer
        2010-01-19 18:05:37,610 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumPeer@487] - LOOKING
        2010-01-19 18:05:37,610 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumPeer@424] - Initializing leader election protocol...
        2010-01-19 18:05:37,612 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@579] - New election: -1
        2010-01-19 18:05:37,613 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:37,615 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:05:37,616 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:37,616 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@193] - Receive new message.
        2010-01-19 18:05:37,617 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:05:37,617 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:37,618 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 100, -1, 1, 100, LOOKING, LOOKING, 100
        2010-01-19 18:05:37,619 - DEBUG [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@465] - id: 100, proposed id: 100, zxid: -1, proposed zxid: -1
        2010-01-19 18:05:37,619 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote
        2010-01-19 18:05:37,619 - WARN [WorkerSender Thread:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:302)
        at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:323)
        at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:296)
        at java.lang.Thread.run(Thread.java:619)
        2010-01-19 18:05:37,621 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:37,622 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:05:37,821 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:37,823 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:05:37,824 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:37,824 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:05:37,825 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:37,826 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:05:37,826 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:37,826 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:05:37,827 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 400
        2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:38,230 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:38,230 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:05:38,231 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:38,231 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:05:38,231 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:38,232 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:05:38,233 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:38,233 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:05:38,233 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 800
        2010-01-19 18:05:39,035 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:39,037 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:05:39,037 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:39,038 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:05:39,038 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:39,039 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:05:39,039 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:39,040 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:05:39,040 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 1600
        2010-01-19 18:05:40,642 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:40,644 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:05:40,645 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:40,645 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:05:40,645 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:40,646 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:05:40,646 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:40,647 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:05:40,647 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 3200
        2010-01-19 18:05:43,848 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:43,850 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:05:43,851 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:43,851 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:05:43,851 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:43,852 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:05:43,852 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:43,853 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:05:43,853 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 6400
        2010-01-19 18:05:50,254 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:05:50,256 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:05:50,256 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:05:50,257 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:05:50,257 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:05:50,258 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:05:50,258 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:05:50,258 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:05:50,259 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 12800
        2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:06:03,061 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:06:03,062 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:06:03,062 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:06:03,062 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:06:03,063 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:06:03,063 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:06:03,064 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:06:03,064 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 25600
        2010-01-19 18:06:28,665 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:28,665 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:28,666 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:28,666 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:06:28,666 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:06:28,667 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:06:28,667 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:06:28,668 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:06:28,668 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:06:28,669 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:06:28,669 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:06:28,669 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:06:28,669 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 51200
        2010-01-19 18:07:02,872 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /127.0.0.1:24048
        2010-01-19 18:07:02,872 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:07:02,872 - DEBUG [NIOServerCxn.Factory:8181:NIOServerCnxn@497] - IOException stack trace
        java.io.IOException: Responded to info probe
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:477)
        at org.apache.zookeeper.server.NIOServerCnxn$Factory.run(NIOServerCnxn.java:221)
        2010-01-19 18:07:02,873 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/127.0.0.1:8181

        remote=/127.0.0.1:24048]
        2010-01-19 18:07:02,873 - DEBUG [NIOServerCxn.Factory:8181:NIOServerCnxn@851] - ignoring exception during input shutdown
        java.net.SocketException: Transport endpoint is not connected
        at sun.nio.ch.SocketChannelImpl.shutdown(Native Method)
        at sun.nio.ch.SocketChannelImpl.shutdownInput(SocketChannelImpl.java:640)
        at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:360)
        at org.apache.zookeeper.server.NIOServerCnxn.close(NIOServerCnxn.java:848)
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:498)
        at org.apache.zookeeper.server.NIOServerCnxn$Factory.run(NIOServerCnxn.java:221)
        2010-01-19 18:07:19,871 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:07:19,871 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:07:19,872 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:07:19,872 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1
        2010-01-19 18:07:19,872 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201
        2010-01-19 18:07:19,873 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888
        java.net.ConnectException: Connection refused
        at sun.nio.ch.Net.connect(Native Method)
        at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507)
        at java.nio.channels.SocketChannel.open(SocketChannel.java:146)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323)
        at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356)
        at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603)
        at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488)
        2010-01-19 18:07:19,873 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102
        2010-01-19 18:07:19,874 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100)
        2010-01-19 18:07:19,874 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200
        2010-01-19 18:07:19,875 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100)
        2010-01-19 18:07:19,875 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101
        2010-01-19 18:07:19,875 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100)
        2010-01-19 18:07:19,875 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000

        ======>logs from server.101<======
        2010-01-19 18:05:13,104 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:34801
        2010-01-19 18:05:13,104 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:13,104 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:34801]
        2010-01-19 18:05:33,106 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:38874
        2010-01-19 18:05:33,106 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:33,106 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:38874]
        2010-01-19 18:05:53,108 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:43283
        2010-01-19 18:05:53,109 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:53,109 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:43283]
        2010-01-19 18:06:13,110 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:47715
        2010-01-19 18:06:13,111 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:13,111 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:47715]
        2010-01-19 18:06:33,113 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:51809
        2010-01-19 18:06:33,114 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:33,114 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:51809]
        2010-01-19 18:06:53,116 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:56212
        2010-01-19 18:06:53,116 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:53,116 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:56212]
        2010-01-19 18:07:13,118 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:60643
        2010-01-19 18:07:13,118 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:07:13,118 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:60643]
        2010-01-19 18:07:33,120 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:36484
        2010-01-19 18:07:33,121 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:07:33,121 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:36484]

        ======>logs from server.102<======
        2010-01-19 18:05:14,026 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:34939
        2010-01-19 18:05:14,027 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:14,027 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:34939]
        2010-01-19 18:05:34,029 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:39025
        2010-01-19 18:05:34,029 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:34,029 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:39025]
        2010-01-19 18:05:54,031 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:43424
        2010-01-19 18:05:54,032 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:54,032 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:43424]
        2010-01-19 18:06:14,034 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:47851
        2010-01-19 18:06:14,034 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:14,035 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:47851]
        2010-01-19 18:06:34,037 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:51961
        2010-01-19 18:06:34,037 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:34,037 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:51961]
        2010-01-19 18:06:35,134 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@583] - Connected to /10.81.13.104:36181 lastZxid 0
        2010-01-19 18:06:35,134 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@615] - Creating new session 0x6623cb7929f71f3d
        2010-01-19 18:06:35,141 - INFO [CommitProcessor:102:NIOServerCnxn@964] - Finished init of 0x6623cb7929f71f3d valid:true
        2010-01-19 18:06:54,040 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:56354
        2010-01-19 18:06:54,040 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:54,041 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:56354]
        2010-01-19 18:07:14,043 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:60779
        2010-01-19 18:07:14,043 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:07:14,043 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:60779]
        2010-01-19 18:07:34,045 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:36637
        2010-01-19 18:07:34,046 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe

        ======>logs from server.200<======
        2010-01-19 18:05:08,565 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:49010
        2010-01-19 18:05:08,566 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:08,566 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:49010]
        2010-01-19 18:05:28,568 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:52876
        2010-01-19 18:05:28,568 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:28,569 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:52876]
        2010-01-19 18:05:48,571 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:56815
        2010-01-19 18:05:48,571 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:05:48,571 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:56815]
        2010-01-19 18:06:08,573 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:60751
        2010-01-19 18:06:08,574 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:08,574 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:60751]
        2010-01-19 18:06:28,576 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:36383
        2010-01-19 18:06:28,576 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:28,576 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:36383]
        2010-01-19 18:06:48,578 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:40335
        2010-01-19 18:06:48,579 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:06:48,579 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:40335]
        2010-01-19 18:07:08,581 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:44282
        2010-01-19 18:07:08,581 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:07:08,582 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:44282]
        2010-01-19 18:07:28,583 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:48132
        2010-01-19 18:07:28,584 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe
        2010-01-19 18:07:28,584 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:48132]

        It seem that server.101, server.102 and server.200 didn't give any election information to server.100 and server.201. Does any one has any idea about this problem?

        thanks!

        Show
        Flavio Junqueira added a comment - I have a quorum with 5 servers, and the configure is as follow ============================================= The number of milliseconds of each tick tickTime=2000 The number of ticks that the initial synchronization phase can take initLimit=5 The number of ticks that can pass between sending a request and getting an acknowledgement syncLimit=2 the directory where the snapshot is stored. dataDir=./data/ the port at which the clients will connect clientPort=8181 zookeeper cluster list server.100=10.23.253.43:8887:8888 server.101=10.23.150.29:8887:8888 server.102=10.23.247.141:8887:8888 server.200=10.65.20.68:8887:8888 server.201=10.65.27.21:8887:8888 ============================================== on Jun 15th, data on two of them, server.100 and server.201, were corrupt due to a network adjustment. The result was that the two servers stayed in the election loop and never went out. The log shows that the corrupt data generated a error zxid. ======>logs from server.100<====== 2010-01-16 21:00:17,352 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote 2010-01-16 21:00:17,353 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (201,100) 2010-01-16 21:00:17,353 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 100, LOOKING, FOLLOWING, 101 2010-01-16 21:00:17,354 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 100, LOOKING, LEADING, 200 2010-01-16 21:00:34,362 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:42103 2010-01-16 21:00:34,362 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-16 21:00:34,362 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.253.43:8181 remote=/10.23.250.215:42103] 2010-01-16 21:00:54,363 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:46338 2010-01-16 21:00:54,363 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-16 21:00:54,364 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.253.43:8181 remote=/10.23.250.215:46338] 2010-01-16 21:01:14,366 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:50894 2010-01-16 21:01:14,366 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-16 21:01:14,366 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.253.43:8181 remote=/10.23.250.215:50894] 2010-01-16 21:01:17,356 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000 2010-01-16 21:01:17,356 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102,100) 2010-01-16 21:01:17,356 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 100, 4335573116, 6, 100, LOOKING, LOOKING, 100 ======>logs from server.201<====== 2010-01-16 21:00:17,864 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote 2010-01-16 21:00:17,864 - ERROR [Thread-11258:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread. 2010-01-16 21:00:17,864 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 201, LOOKING, FOLLOWING, 102 2010-01-16 21:00:17,864 - WARN [Thread-11258:QuorumCnxManager$SendWorker@554] - Send worker leaving thread 2010-01-16 21:00:17,864 - WARN [Thread-11259:QuorumCnxManager$RecvWorker@621] - Connection broken: java.nio.channels.ClosedChannelException at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:113) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:156) at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:594) 2010-01-16 21:00:17,864 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@706] - Notification: 200, 40, 5, 201, LOOKING, LEADING, 200 2010-01-16 21:00:18,554 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:59369 2010-01-16 21:00:18,554 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-16 21:00:18,554 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.27.21:8181 remote=/10.65.7.48:59369] 2010-01-16 21:00:38,556 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:34969 2010-01-16 21:00:38,556 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-16 21:00:38,556 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.27.21:8181 remote=/10.65.7.48:34969] 2010-01-16 21:00:58,558 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:38935 2010-01-16 21:00:58,558 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-16 21:00:58,558 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.27.21:8181 remote=/10.65.7.48:38935] 2010-01-16 21:01:17,368 - ERROR [Thread-11260:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread. 2010-01-16 21:01:17,368 - WARN [Thread-11261:QuorumCnxManager$RecvWorker@621] - Connection broken: java.nio.channels.ClosedChannelException at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:113) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:156) at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:594) 2010-01-16 21:01:17,368 - WARN [Thread-11260:QuorumCnxManager$SendWorker@554] - Send worker leaving thread 2010-01-16 21:01:17,866 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000 2010-01-16 21:01:17,867 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 201, 4335618537, 6, 201, LOOKING, LOOKING, 201 2010-01-16 21:01:17,867 - ERROR [Thread-11262:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread. The server.101, server.102 and server.200 seems working well. ======>server.101<====== Zookeeper version: 3.2.1-808558, built on 08/27/2009 18:48 GMT Clients: ... Latency min/avg/max: 0/0/3016 Received: 190409661 Sent: 0 Outstanding: 0 Zxid: 0x102837dd7 Mode: follower Node count: 397 ======>server.102<====== Zookeeper version: 3.2.1-808558, built on 08/27/2009 18:48 GMT Clients: ... Latency min/avg/max: 0/0/1999 Received: 201910241 Sent: 0 Outstanding: 0 Zxid: 0x102837ddb Mode: follower Node count: 397 Zookeeper version: 3.2.1-808558, built on 08/27/2009 18:48 GMT Clients: ... Latency min/avg/max: 0/0/4004 Received: 318497545 Sent: 0 Outstanding: 0 Zxid: 0x102837ddf Mode: leader Node count: 397 It may be caused by this bug https://issues.apache.org/jira/browse/ZOOKEEPER-596 . However, the strange thing is that when I clean up the corrupt data, the server.100 and the server.201 still cannot join the quorum. Try to start server.201 ======>logs from server.201<====== 2010-01-19 11:00:12,885 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000 2010-01-19 11:00:12,885 - DEBUG [WorkerSender Thread:QuorumCnxManager@341] - There is a connection for server 102 2010-01-19 11:00:12,886 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 100 2010-01-19 11:00:12,886 - WARN [WorkerSender Thread:QuorumCnxManager@336] - Cannot open channel to 100 at election address /10.23.253.43:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:302) at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:323) at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:296) at java.lang.Thread.run(Thread.java:619) 2010-01-19 11:00:12,887 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 11:00:12,888 - DEBUG [WorkerSender Thread:QuorumCnxManager$SendWorker@468] - Address of remote peer: 101 2010-01-19 11:00:12,889 - DEBUG [WorkerSender Thread:QuorumCnxManager@341] - There is a connection for server 200 2010-01-19 11:00:12,889 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@193] - Receive new message. 2010-01-19 11:00:12,889 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 201, -1, 1, 201, LOOKING, LOOKING, 201 2010-01-19 11:00:12,889 - WARN [Thread-27:QuorumCnxManager$RecvWorker@621] - Connection broken: java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:594) 2010-01-19 11:00:12,890 - ERROR [Thread-26:QuorumCnxManager$SendWorker@523] - Failed to send last message. Shutting down thread. 2010-01-19 11:00:12,890 - DEBUG [Thread-26:QuorumCnxManager$SendWorker@487] - Calling finish 2010-01-19 11:00:12,889 - DEBUG [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@465] - id: 201, proposed id: 201, zxid: -1, proposed zxid: -1 2010-01-19 11:00:12,890 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote 2010-01-19 11:00:12,891 - WARN [Thread-26:QuorumCnxManager$SendWorker@554] - Send worker leaving thread 2010-01-19 11:01:12,892 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 0 ======>logs from server.100<====== at this time, the server.100 is down ======>logs from server.101<====== 2010-01-19 11:00:05,444 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:35215 2010-01-19 11:00:05,445 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:05,446 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:35215] 2010-01-19 11:00:25,448 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:39165 2010-01-19 11:00:25,448 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:25,448 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:39165] 2010-01-19 11:00:45,451 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:43705 2010-01-19 11:00:45,451 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:45,451 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.150.29:8181 remote=/10.23.250.215:43705] 2010-01-19 11:01:05,453 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:48062 2010-01-19 11:01:05,453 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:01:05,453 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChan nel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:48062] 2010-01-19 11:01:25,455 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:52006 2010-01-19 11:01:25,455 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe ======>logs from server.102<====== 2010-01-19 11:00:06,769 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:35661 2010-01-19 11:00:06,770 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:06,770 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:35661] 2010-01-19 11:00:26,773 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:39617 2010-01-19 11:00:26,773 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:26,773 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:39617] 2010-01-19 11:00:46,776 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:44160 2010-01-19 11:00:46,777 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:46,777 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:44160] 2010-01-19 11:01:06,778 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:48506 2010-01-19 11:01:06,779 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:01:06,779 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:48506] 2010-01-19 11:01:26,781 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.23.250.215:52452 2010-01-19 11:01:26,781 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:01:26,781 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.23.247.141:8181 remote=/10.23.250.215:52452] ======>logs from server.200<====== 2010-01-19 11:00:05,586 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:59644 2010-01-19 11:00:05,586 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:05,587 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:59644] 2010-01-19 11:00:25,589 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:35356 2010-01-19 11:00:25,589 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:25,590 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:35356] 2010-01-19 11:00:45,592 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:39554 2010-01-19 11:00:45,592 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:00:45,592 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:39554] 2010-01-19 11:01:05,594 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:44016 2010-01-19 11:01:05,594 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:01:05,594 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:44016] 2010-01-19 11:01:25,597 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@627] - Processing ruok command from /10.65.7.48:47944 2010-01-19 11:01:25,597 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 11:01:25,597 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/10.65.20.68:8181 remote=/10.65.7.48:47944] Try to start server.100 ======>logs from server.201<====== at this time, the server.201 is down ======>logs from server.100<====== 2010-01-19 18:05:37,612 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@579] - New election: -1 2010-01-19 18:05:37,613 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:37,615 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:37,616 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:37,616 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@193] - Receive new message. 2010-01-19 18:05:37,617 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:37,617 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:37,618 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 100, -1, 1, 100, LOOKING, LOOKING, 100 2010-01-19 18:05:37,619 - DEBUG [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@465] - id: 100, proposed id: 100, zxid: -1, proposed zxid: -1 2010-01-19 18:05:37,619 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote 2010-01-19 18:05:37,619 - WARN [WorkerSender Thread:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:302) at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:323) at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:296) at java.lang.Thread.run(Thread.java:619) 2010-01-19 18:05:37,621 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:37,622 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) [rd@tc-bps-zk00 log] $ cat zookeeper.log 2010-01-19 18:05:37,547 - INFO [main:QuorumPeerConfig@80] - Reading configuration from: /home/passport/zookeeper/bin/../conf/zoo.cfg 2010-01-19 18:05:37,552 - INFO [main:QuorumPeerConfig@232] - Defaulting to majority quorums 2010-01-19 18:05:37,556 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:hiearchy=default 2010-01-19 18:05:37,557 - DEBUG [main:HierarchyDynamicMBean@254] - postRegister is called. 2010-01-19 18:05:37,559 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=root 2010-01-19 18:05:37,559 - DEBUG [main:LoggerDynamicMBean@256] - Adding AppenderMBean for appender named NOTICEFILE 2010-01-19 18:05:37,562 - DEBUG [main:AppenderDynamicMBean@152] - getMBeanInfo called. 2010-01-19 18:05:37,562 - DEBUG [main:AppenderDynamicMBean@309] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:appender=NOTICEFILE 2010-01-19 18:05:37,563 - DEBUG [main:AppenderDynamicMBean@191] - Adding LayoutMBean:NOTICEFILE,layout=org.apache.log4j.PatternLayout 2010-01-19 18:05:37,565 - DEBUG [main:LayoutDynamicMBean@138] - getMBeanInfo called. 2010-01-19 18:05:37,565 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:appender=NOTICEFILE,layout=org.apache.log4j.PatternLayout 2010-01-19 18:05:37,566 - DEBUG [main:LoggerDynamicMBean@256] - Adding AppenderMBean for appender named WARNFILE 2010-01-19 18:05:37,567 - DEBUG [main:AppenderDynamicMBean@152] - getMBeanInfo called. 2010-01-19 18:05:37,568 - DEBUG [main:AppenderDynamicMBean@309] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:appender=WARNFILE 2010-01-19 18:05:37,568 - DEBUG [main:AppenderDynamicMBean@191] - Adding LayoutMBean:WARNFILE,layout=org.apache.log4j.PatternLayout 2010-01-19 18:05:37,569 - DEBUG [main:LayoutDynamicMBean@138] - getMBeanInfo called. 2010-01-19 18:05:37,570 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:appender=WARNFILE,layout=org.apache.log4j.PatternLayout 2010-01-19 18:05:37,571 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [root] as listener. 2010-01-19 18:05:37,571 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=org.apache.log4j.jmx.LayoutDynamicMBean 2010-01-19 18:05:37,572 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.LayoutDynamicMBean] as listener. 2010-01-19 18:05:37,573 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=org.apache.zookeeper.server.quorum.QuorumPeerMain 2010-01-19 18:05:37,573 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.zookeeper.server.quorum.QuorumPeerMain] as listener. 2010-01-19 18:05:37,573 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=org.apache.log4j.jmx.LoggerDynamicMBean 2010-01-19 18:05:37,574 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.LoggerDynamicMBean] as listener. 2010-01-19 18:05:37,574 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=org.apache.zookeeper.server.quorum.QuorumPeerConfig 2010-01-19 18:05:37,574 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.zookeeper.server.quorum.QuorumPeerConfig] as listener. 2010-01-19 18:05:37,575 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=org.apache.log4j.jmx.HierarchyDynamicMBean 2010-01-19 18:05:37,575 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.HierarchyDynamicMBean] as listener. 2010-01-19 18:05:37,575 - DEBUG [main:AbstractDynamicMBean@124] - preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@2be9cb75, name=log4j:logger=org.apache.log4j.jmx.AppenderDynamicMBean 2010-01-19 18:05:37,576 - DEBUG [main:HierarchyDynamicMBean@126] - ---Adding logger [org.apache.log4j.jmx.AppenderDynamicMBean] as listener. 2010-01-19 18:05:37,576 - INFO [main:QuorumPeerMain@118] - Starting quorum peer 2010-01-19 18:05:37,602 - INFO [Thread-1:QuorumCnxManager$Listener@409] - My election bind port: 8888 2010-01-19 18:05:37,604 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumPeer@451] - Starting quorum peer 2010-01-19 18:05:37,610 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumPeer@487] - LOOKING 2010-01-19 18:05:37,610 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumPeer@424] - Initializing leader election protocol... 2010-01-19 18:05:37,612 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@579] - New election: -1 2010-01-19 18:05:37,613 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:37,615 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:37,616 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:37,616 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@193] - Receive new message. 2010-01-19 18:05:37,617 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:37,617 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:37,618 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@618] - Notification: 100, -1, 1, 100, LOOKING, LOOKING, 100 2010-01-19 18:05:37,619 - DEBUG [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@465] - id: 100, proposed id: 100, zxid: -1, proposed zxid: -1 2010-01-19 18:05:37,619 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@642] - Adding vote 2010-01-19 18:05:37,619 - WARN [WorkerSender Thread:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:302) at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:323) at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:296) at java.lang.Thread.run(Thread.java:619) 2010-01-19 18:05:37,621 - DEBUG [WorkerSender Thread:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:37,622 - INFO [WorkerSender Thread:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:05:37,821 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:37,822 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:37,823 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:05:37,824 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:37,824 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:37,825 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:37,826 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:05:37,826 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:37,826 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:37,827 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 400 2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:38,229 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:38,230 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:38,230 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:05:38,231 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:38,231 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:38,231 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:38,232 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:05:38,233 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:38,233 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:38,233 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 800 2010-01-19 18:05:39,035 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:39,036 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:39,037 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:05:39,037 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:39,038 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:39,038 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:39,039 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:05:39,039 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:39,040 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:39,040 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 1600 2010-01-19 18:05:40,642 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:40,643 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:40,644 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:05:40,645 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:40,645 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:40,645 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:40,646 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:05:40,646 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:40,647 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:40,647 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 3200 2010-01-19 18:05:43,848 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:43,849 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:43,850 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:05:43,851 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:43,851 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:43,851 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:43,852 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:05:43,852 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:43,853 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:43,853 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 6400 2010-01-19 18:05:50,254 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:05:50,255 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:05:50,256 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:05:50,256 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:05:50,257 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:05:50,257 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:05:50,258 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:05:50,258 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:05:50,258 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:05:50,259 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 12800 2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:03,060 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:06:03,061 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:06:03,062 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:06:03,062 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:06:03,062 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:06:03,063 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:06:03,063 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:06:03,064 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:06:03,064 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 25600 2010-01-19 18:06:28,665 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:28,665 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:28,666 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:28,666 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:06:28,666 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:06:28,667 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:06:28,667 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:06:28,668 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:06:28,668 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:06:28,669 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:06:28,669 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:06:28,669 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:06:28,669 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 51200 2010-01-19 18:07:02,872 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /127.0.0.1:24048 2010-01-19 18:07:02,872 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:07:02,872 - DEBUG [NIOServerCxn.Factory:8181:NIOServerCnxn@497] - IOException stack trace java.io.IOException: Responded to info probe at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:477) at org.apache.zookeeper.server.NIOServerCnxn$Factory.run(NIOServerCnxn.java:221) 2010-01-19 18:07:02,873 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/127.0.0.1:8181 remote=/127.0.0.1:24048] 2010-01-19 18:07:02,873 - DEBUG [NIOServerCxn.Factory:8181:NIOServerCnxn@851] - ignoring exception during input shutdown java.net.SocketException: Transport endpoint is not connected at sun.nio.ch.SocketChannelImpl.shutdown(Native Method) at sun.nio.ch.SocketChannelImpl.shutdownInput(SocketChannelImpl.java:640) at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:360) at org.apache.zookeeper.server.NIOServerCnxn.close(NIOServerCnxn.java:848) at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:498) at org.apache.zookeeper.server.NIOServerCnxn$Factory.run(NIOServerCnxn.java:221) 2010-01-19 18:07:19,871 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:07:19,871 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:07:19,872 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:07:19,872 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@366] - Queue size: 1 2010-01-19 18:07:19,872 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 201 2010-01-19 18:07:19,873 - WARN [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@336] - Cannot open channel to 201 at election address /10.65.27.21:8888 java.net.ConnectException: Connection refused at sun.nio.ch.Net.connect(Native Method) at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:507) at java.nio.channels.SocketChannel.open(SocketChannel.java:146) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:323) at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:356) at org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:603) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:488) 2010-01-19 18:07:19,873 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 102 2010-01-19 18:07:19,874 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (102, 100) 2010-01-19 18:07:19,874 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 200 2010-01-19 18:07:19,875 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (200, 100) 2010-01-19 18:07:19,875 - DEBUG [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@322] - Opening channel to server 101 2010-01-19 18:07:19,875 - INFO [QuorumPeer:/0.0.0.0:8181:QuorumCnxManager@154] - Have smaller server identifier, so dropping the connection: (101, 100) 2010-01-19 18:07:19,875 - INFO [QuorumPeer:/0.0.0.0:8181:FastLeaderElection@612] - Notification time out: 60000 ======>logs from server.101<====== 2010-01-19 18:05:13,104 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:34801 2010-01-19 18:05:13,104 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:13,104 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:34801] 2010-01-19 18:05:33,106 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:38874 2010-01-19 18:05:33,106 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:33,106 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:38874] 2010-01-19 18:05:53,108 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:43283 2010-01-19 18:05:53,109 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:53,109 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:43283] 2010-01-19 18:06:13,110 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:47715 2010-01-19 18:06:13,111 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:13,111 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:47715] 2010-01-19 18:06:33,113 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:51809 2010-01-19 18:06:33,114 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:33,114 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:51809] 2010-01-19 18:06:53,116 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:56212 2010-01-19 18:06:53,116 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:53,116 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:56212] 2010-01-19 18:07:13,118 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:60643 2010-01-19 18:07:13,118 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:07:13,118 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:60643] 2010-01-19 18:07:33,120 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:36484 2010-01-19 18:07:33,121 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:07:33,121 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.150.29:8181 remote=/10.23.250.215:36484] ======>logs from server.102<====== 2010-01-19 18:05:14,026 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:34939 2010-01-19 18:05:14,027 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:14,027 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.247.141:8181 remote=/10.23.250.215:34939] 2010-01-19 18:05:34,029 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:39025 2010-01-19 18:05:34,029 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:34,029 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.247.141:8181 remote=/10.23.250.215:39025] 2010-01-19 18:05:54,031 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:43424 2010-01-19 18:05:54,032 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:54,032 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.247.141:8181 remote=/10.23.250.215:43424] 2010-01-19 18:06:14,034 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:47851 2010-01-19 18:06:14,034 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:14,035 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.247.141:8181 remote=/10.23.250.215:47851] 2010-01-19 18:06:34,037 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:51961 2010-01-19 18:06:34,037 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:34,037 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.247.141:8181 remote=/10.23.250.215:51961] 2010-01-19 18:06:35,134 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@583] - Connected to /10.81.13.104:36181 lastZxid 0 2010-01-19 18:06:35,134 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@615] - Creating new session 0x6623cb7929f71f3d 2010-01-19 18:06:35,141 - INFO [CommitProcessor:102:NIOServerCnxn@964] - Finished init of 0x6623cb7929f71f3d valid:true 2010-01-19 18:06:54,040 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:56354 2010-01-19 18:06:54,040 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:54,041 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.247.141:8181 remote=/10.23.250.215:56354] 2010-01-19 18:07:14,043 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:60779 2010-01-19 18:07:14,043 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:07:14,043 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.23.247.141:8181 remote=/10.23.250.215:60779] 2010-01-19 18:07:34,045 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.23.250.215:36637 2010-01-19 18:07:34,046 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe ======>logs from server.200<====== 2010-01-19 18:05:08,565 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:49010 2010-01-19 18:05:08,566 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:08,566 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:49010] 2010-01-19 18:05:28,568 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:52876 2010-01-19 18:05:28,568 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:28,569 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:52876] 2010-01-19 18:05:48,571 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:56815 2010-01-19 18:05:48,571 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:05:48,571 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:56815] 2010-01-19 18:06:08,573 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:60751 2010-01-19 18:06:08,574 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:08,574 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:60751] 2010-01-19 18:06:28,576 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:36383 2010-01-19 18:06:28,576 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:28,576 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:36383] 2010-01-19 18:06:48,578 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:40335 2010-01-19 18:06:48,579 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:06:48,579 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:40335] 2010-01-19 18:07:08,581 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:44282 2010-01-19 18:07:08,581 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:07:08,582 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:44282] 2010-01-19 18:07:28,583 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@698] - Processing stat command from /10.65.7.48:48132 2010-01-19 18:07:28,584 - WARN [NIOServerCxn.Factory:8181:NIOServerCnxn@494] - Exception causing close of session 0x0 due to java.io.IOException: Responded to info probe 2010-01-19 18:07:28,584 - INFO [NIOServerCxn.Factory:8181:NIOServerCnxn@833] - closing session:0x0 NIOServerCnxn: java.nio.channels.SocketChannel [connected local=/10.65.20.68:8181 remote=/10.65.7.48:48132] It seem that server.101, server.102 and server.200 didn't give any election information to server.100 and server.201. Does any one has any idea about this problem? thanks!

          People

          • Assignee:
            Unassigned
            Reporter:
            Qian Ye
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development